fn: clean api tests: removed multi log (#801)

fn-test-utils covers this, with sleep in between.

api/logs/mock.go

@@ -1,30 +1,32 @@
 package logs
 
 import (
+	"bytes"
 	"context"
 	"io"
+	"io/ioutil"
 
 	"github.com/fnproject/fn/api/models"
 )
 
 type mock struct {
-	Logs map[string]io.Reader
+	Logs map[string][]byte
 }
 
 func NewMock() models.LogStore {
-	return &mock{make(map[string]io.Reader)}
+	return &mock{make(map[string][]byte)}
 }
 
 func (m *mock) InsertLog(ctx context.Context, appName, callID string, callLog io.Reader) error {
-	m.Logs[callID] = callLog
+	bytes, err := ioutil.ReadAll(callLog)
-	return nil
+	m.Logs[callID] = bytes
+	return err
 }
 
 func (m *mock) GetLog(ctx context.Context, appName, callID string) (io.Reader, error) {
-	logEntry := m.Logs[callID]
+	logEntry, ok := m.Logs[callID]
-	if logEntry == nil {
+	if !ok {
 		return nil, models.ErrCallLogNotFound
 	}
-
+	return bytes.NewReader(logEntry), nil
-	return logEntry, nil
 }

api/server/runner_test.go

@@ -153,9 +153,7 @@ func TestRouteRunnerExecution(t *testing.T) {
 	rnr, cancelrnr := testRunner(t, ds)
 	defer cancelrnr()
 
-	fnl := logs.NewMock()
+	srv := testServer(ds, &mqs.Mock{}, ds, rnr, ServerTypeFull)
-
-	srv := testServer(ds, &mqs.Mock{}, fnl, rnr, ServerTypeFull)
 
 	expHeaders := map[string][]string{"X-Function": {"Test"}, "Content-Type": {"application/json; charset=utf-8"}}
 	expCTHeaders := map[string][]string{"X-Function": {"Test"}, "Content-Type": {"foo/bar"}}
@@ -168,57 +166,63 @@ func TestRouteRunnerExecution(t *testing.T) {
 	respTypeLie := `{"responseContentType": "foo/bar", "sleepTime":0, "isDebug": true}` // Content-Type: foo/bar
 	respTypeJason := `{"jasonContentType": "foo/bar", "sleepTime":0, "isDebug": true}`  // Content-Type: foo/bar
 
+	// sleep between logs and with debug enabled, fn-test-utils will log header/footer below:
+	multiLog := `{"sleepTime": 1, "isDebug": true}`
+	multiLogExpect := []string{"BeginOfLogs", "EndOfLogs"}
+
 	for i, test := range []struct {
-		path              string
+		path               string
-		body              string
+		body               string
-		method            string
+		method             string
-		expectedCode      int
+		expectedCode       int
-		expectedHeaders   map[string][]string
+		expectedHeaders    map[string][]string
-		expectedErrSubStr string
+		expectedErrSubStr  string
+		expectedLogsSubStr []string
 	}{
-		{"/r/myapp/", ok, "GET", http.StatusOK, expHeaders, ""},
+		{"/r/myapp/", ok, "GET", http.StatusOK, expHeaders, "", nil},
 
-		{"/r/myapp/myhot", badHttp, "GET", http.StatusBadGateway, expHeaders, "invalid http response"},
+		{"/r/myapp/myhot", badHttp, "GET", http.StatusBadGateway, expHeaders, "invalid http response", nil},
 		// hot container now back to normal, we should get OK
-		{"/r/myapp/myhot", ok, "GET", http.StatusOK, expHeaders, ""},
+		{"/r/myapp/myhot", ok, "GET", http.StatusOK, expHeaders, "", nil},
 
-		{"/r/myapp/myhotjason", ok, "GET", http.StatusOK, expHeaders, ""},
+		{"/r/myapp/myhotjason", ok, "GET", http.StatusOK, expHeaders, "", nil},
 
-		{"/r/myapp/myhot", respTypeLie, "GET", http.StatusOK, expCTHeaders, ""},
+		{"/r/myapp/myhot", respTypeLie, "GET", http.StatusOK, expCTHeaders, "", nil},
-		{"/r/myapp/myhotjason", respTypeLie, "GET", http.StatusOK, expCTHeaders, ""},
+		{"/r/myapp/myhotjason", respTypeLie, "GET", http.StatusOK, expCTHeaders, "", nil},
-		{"/r/myapp/myhotjason", respTypeJason, "GET", http.StatusOK, expCTHeaders, ""},
+		{"/r/myapp/myhotjason", respTypeJason, "GET", http.StatusOK, expCTHeaders, "", nil},
 
-		{"/r/myapp/myhot", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid http response"},
+		{"/r/myapp/myhot", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid http response", nil},
-		{"/r/myapp/myhotjason", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid json response"},
+		{"/r/myapp/myhotjason", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid json response", nil},
 
-		{"/r/myapp/myroute", ok, "GET", http.StatusOK, expHeaders, ""},
+		{"/r/myapp/myroute", ok, "GET", http.StatusOK, expHeaders, "", nil},
-		{"/r/myapp/myerror", crasher, "GET", http.StatusBadGateway, expHeaders, "container exit code 2"},
+		{"/r/myapp/myerror", crasher, "GET", http.StatusBadGateway, expHeaders, "container exit code 2", nil},
-		{"/r/myapp/mydne", ``, "GET", http.StatusNotFound, nil, "pull access denied"},
+		{"/r/myapp/mydne", ``, "GET", http.StatusNotFound, nil, "pull access denied", nil},
-		{"/r/myapp/mydnehot", ``, "GET", http.StatusNotFound, nil, "pull access denied"},
+		{"/r/myapp/mydnehot", ``, "GET", http.StatusNotFound, nil, "pull access denied", nil},
 		// hit a registry that doesn't exist, make sure the real error body gets plumbed out
-		{"/r/myapp/mydneregistry", ``, "GET", http.StatusInternalServerError, nil, "connection refused"},
+		{"/r/myapp/mydneregistry", ``, "GET", http.StatusInternalServerError, nil, "connection refused", nil},
 
-		{"/r/myapp/myoom", oomer, "GET", http.StatusBadGateway, nil, "container out of memory"},
+		{"/r/myapp/myoom", oomer, "GET", http.StatusBadGateway, nil, "container out of memory", nil},
+		{"/r/myapp/myhot", multiLog, "GET", http.StatusOK, nil, "", multiLogExpect},
 	} {
 		body := strings.NewReader(test.body)
 		_, rec := routerRequest(t, srv.Router, test.method, test.path, body)
 		respBytes, _ := ioutil.ReadAll(rec.Body)
 		respBody := string(respBytes)
-		maxLog := len(respBody)
+		maxBody := len(respBody)
-		if maxLog > 1024 {
+		if maxBody > 1024 {
-			maxLog = 1024
+			maxBody = 1024
 		}
 
 		if rec.Code != test.expectedCode {
 			isFailure = true
 			t.Errorf("Test %d: Expected status code to be %d but was %d. body: %s",
-				i, test.expectedCode, rec.Code, respBody[:maxLog])
+				i, test.expectedCode, rec.Code, respBody[:maxBody])
 		}
 
 		if test.expectedErrSubStr != "" && !strings.Contains(respBody, test.expectedErrSubStr) {
 			isFailure = true
 			t.Errorf("Test %d: Expected response to include %s but got body: %s",
-				i, test.expectedErrSubStr, respBody[:maxLog])
+				i, test.expectedErrSubStr, respBody[:maxBody])
 
 		}
 
@@ -231,6 +235,37 @@ func TestRouteRunnerExecution(t *testing.T) {
 				}
 			}
 		}
+
+		if test.expectedLogsSubStr != nil {
+			callID := rec.Header().Get("Fn_call_id")
+
+			logReader, err := ds.GetLog(context.Background(), "myapp", callID)
+			if err != nil {
+				isFailure = true
+				t.Errorf("Test %d: GetLog for call_id:%s returned err %s",
+					i, callID, err.Error())
+			} else {
+				logBytes, err := ioutil.ReadAll(logReader)
+				if err != nil {
+					isFailure = true
+					t.Errorf("Test %d: GetLog read IO call_id:%s returned err %s",
+						i, callID, err.Error())
+				} else {
+					logBody := string(logBytes)
+					maxLog := len(logBody)
+					if maxLog > 1024 {
+						maxLog = 1024
+					}
+					for _, match := range test.expectedLogsSubStr {
+						if !strings.Contains(logBody, match) {
+							isFailure = true
+							t.Errorf("Test %d: GetLog read IO call_id:%s cannot find: %s in logs: %s",
+								i, callID, match, logBody[:maxLog])
+						}
+					}
+				}
+			}
+		}
 	}
 }
 

images/fn-test-utils/fn-test-utils.go

@@ -50,8 +50,8 @@ type AppRequest struct {
 	AllocateMemory int `json:"allocateMemory,omitempty"`
 	// leak RAM forever
 	LeakMemory int `json:"leakMemory,omitempty"`
-	// respond with partial output
+	// duplicate trailer if > 0
-	ResponseSize int `json:"responseSize,omitempty"`
+	TrailerRepeat int `json:"trailerRepeat,omitempty"`
 	// corrupt http or json
 	InvalidResponse bool `json:"invalidResponse,omitempty"`
 	// TODO: simulate slow read/slow write
@@ -72,6 +72,7 @@ type AppResponse struct {
 	Headers http.Header       `json:"header"`
 	Config  map[string]string `json:"config"`
 	Data    map[string]string `json:"data"`
+	Trailer []string          `json:"trailer"`
 }
 
 func init() {
@@ -88,6 +89,15 @@ func getTotalLeaks() int {
 
 func AppHandler(ctx context.Context, in io.Reader, out io.Writer) {
 	req, resp := processRequest(ctx, in)
+
+	if req.InvalidResponse {
+		_, err := io.Copy(out, strings.NewReader(InvalidResponseStr))
+		if err != nil {
+			log.Printf("io copy error %v", err)
+			panic(err.Error())
+		}
+	}
+
 	var outto fdkresponse
 	outto.Writer = out
 	finalizeRequest(&outto, req, resp)
@@ -125,6 +135,7 @@ func processRequest(ctx context.Context, in io.Reader) (*AppRequest, *AppRespons
 
 	if request.IsDebug {
 		format, _ := os.LookupEnv("FN_FORMAT")
+		log.Printf("BeginOfLogs")
 		log.Printf("Received format %v", format)
 		log.Printf("Received request %#v", request)
 		log.Printf("Received headers %v", fnctx.Header)
@@ -190,8 +201,17 @@ func processRequest(ctx context.Context, in io.Reader) (*AppRequest, *AppRespons
 		Request: request,
 		Headers: fnctx.Header,
 		Config:  fnctx.Config,
+		Trailer: make([]string, 0, request.TrailerRepeat),
 	}
 
+	for i := request.TrailerRepeat; i > 0; i-- {
+		resp.Trailer = append(resp.Trailer, request.EchoContent)
+	}
+
+	// Well, almost true.. If panic/errors, we may print stuff after this
+	if request.IsDebug {
+		log.Printf("EndOfLogs")
+	}
 	return &request, &resp
 }
 
@@ -226,7 +246,7 @@ func testDoHTTP(ctx context.Context, in io.Reader, out io.Writer) {
 	for {
 		err := testDoHTTPOnce(ctx, in, out, &buf, hdr)
 		if err != nil {
-			break
+			panic("testDoHTTPOnce: " + err.Error())
 		}
 	}
 }
@@ -238,7 +258,7 @@ func testDoJSON(ctx context.Context, in io.Reader, out io.Writer) {
 	for {
 		err := testDoJSONOnce(ctx, in, out, &buf, hdr)
 		if err != nil {
-			break
+			panic("testDoJSONOnce: " + err.Error())
 		}
 	}
 }
@@ -251,13 +271,12 @@ func testDoJSONOnce(ctx context.Context, in io.Reader, out io.Writer, buf *bytes
 	resp.Status = 200
 	resp.Header = hdr
 
-	responseSize := 0
-
 	var jsonRequest fdkutils.JsonIn
 	err := json.NewDecoder(in).Decode(&jsonRequest)
 	if err != nil {
 		// stdin now closed
 		if err == io.EOF {
+			log.Printf("json decoder read EOF %v", err)
 			return err
 		}
 		resp.Status = http.StatusInternalServerError
@@ -274,23 +293,20 @@ func testDoJSONOnce(ctx context.Context, in io.Reader, out io.Writer, buf *bytes
 			io.Copy(out, strings.NewReader(InvalidResponseStr))
 		}
 
-		responseSize = appReq.ResponseSize
 	}
 
 	jsonResponse := getJSONResp(buf, &resp, &jsonRequest)
 
-	if responseSize > 0 {
+	b, err := json.Marshal(jsonResponse)
-		b, err := json.Marshal(jsonResponse)
+	if err != nil {
-		if err != nil {
+		log.Printf("json marshal error %v", err)
-			return err
+		return err
-		}
+	}
-		if len(b) > responseSize {
+
-			responseSize = len(b)
+	_, err = out.Write(b)
-		}
+	if err != nil {
-		b = b[:responseSize]
+		log.Printf("json write error %v", err)
-		out.Write(b)
+		return err
-	} else {
-		json.NewEncoder(out).Encode(jsonResponse)
 	}
 
 	return nil
@@ -324,12 +340,11 @@ func testDoHTTPOnce(ctx context.Context, in io.Reader, out io.Writer, buf *bytes
 	resp.Status = 200
 	resp.Header = hdr
 
-	responseSize := 0
-
 	req, err := http.ReadRequest(bufio.NewReader(in))
 	if err != nil {
 		// stdin now closed
 		if err == io.EOF {
+			log.Printf("http read EOF %v", err)
 			return err
 		}
 		// TODO it would be nice if we could let the user format this response to their preferred style..
@@ -348,33 +363,14 @@ func testDoHTTPOnce(ctx context.Context, in io.Reader, out io.Writer, buf *bytes
 			io.Copy(out, strings.NewReader(InvalidResponseStr))
 		}
 
-		responseSize = appReq.ResponseSize
 	}
 
 	hResp := fdkutils.GetHTTPResp(buf, &resp.Response, req)
 
-	if responseSize > 0 {
+	err = hResp.Write(out)
-
+	if err != nil {
-		var buf bytes.Buffer
+		log.Printf("http response write error %v", err)
-		bufWriter := bufio.NewWriter(&buf)
+		return err
-
-		err := hResp.Write(bufWriter)
-		if err != nil {
-			return err
-		}
-
-		bufReader := bufio.NewReader(&buf)
-
-		if buf.Len() > responseSize {
-			responseSize = buf.Len()
-		}
-
-		_, err = io.CopyN(out, bufReader, int64(responseSize))
-		if err != nil {
-			return err
-		}
-	} else {
-		hResp.Write(out)
 	}
 
 	return nil

test/fn-api-tests/exec_test.go

@@ -257,51 +257,6 @@ func TestCanCauseTimeout(t *testing.T) {
 	DeleteApp(t, s.Context, s.Client, s.AppName)
 }
 
-func TestMultiLog(t *testing.T) {
-	t.Parallel()
-	s := SetupDefaultSuite()
-	routePath := "/multi-log"
-	image := "funcy/multi-log:0.0.1"
-	routeType := "sync"
-
-	CreateApp(t, s.Context, s.Client, s.AppName, map[string]string{})
-	CreateRoute(t, s.Context, s.Client, s.AppName, routePath, image, routeType,
-		s.Format, s.Timeout, s.IdleTimeout, s.RouteConfig, s.RouteHeaders)
-
-	u := url.URL{
-		Scheme: "http",
-		Host:   Host(),
-	}
-	u.Path = path.Join(u.Path, "r", s.AppName, routePath)
-
-	callID := CallSync(t, u, &bytes.Buffer{})
-
-	cfg := &operations.GetAppsAppCallsCallLogParams{
-		Call:    callID,
-		App:     s.AppName,
-		Context: s.Context,
-	}
-
-	logObj, err := s.Client.Operations.GetAppsAppCallsCallLog(cfg)
-	if err != nil {
-		t.Error(err.Error())
-	} else {
-		if logObj.Payload == "" {
-			t.Errorf("Log entry must not be empty!")
-		}
-		if !strings.Contains(logObj.Payload, "First line") {
-			t.Errorf("Log entry must contain `First line` "+
-				"string, but got: %v", logObj.Payload)
-		}
-		if !strings.Contains(logObj.Payload, "Second line") {
-			t.Errorf("Log entry must contain `Second line` "+
-				"string, but got: %v", logObj.Payload)
-		}
-	}
-
-	DeleteApp(t, s.Context, s.Client, s.AppName)
-}
-
 func TestCallResponseHeadersMatch(t *testing.T) {
 	t.Parallel()
 	s := SetupDefaultSuite()

test/fn-api-tests/fn/multi-log/Dockerfile

@@ -1,8 +0,0 @@
-FROM fnproject/go:dev as build-stage
-WORKDIR /function
-ADD . /src
-RUN cd /src && go build -o func
-FROM fnproject/go
-WORKDIR /function
-COPY --from=build-stage /src/func /function/
-ENTRYPOINT ["./func"]

test/fn-api-tests/fn/multi-log/func.yaml

@@ -1,5 +0,0 @@
-name: fnproject/multi-log
-version: 0.0.1
-runtime: go
-entrypoint: ./func
-path: /multi-log

test/fn-api-tests/fn/multi-log/main.go

@@ -1,14 +0,0 @@
-package main
-
-import (
-	"fmt"
-	"os"
-	"time"
-)
-
-func main() {
-	fmt.Fprintln(os.Stderr, "First line")
-	fmt.Fprintln(os.Stdout, "Ok")
-	time.Sleep(3 * time.Second)
-	fmt.Fprintln(os.Stderr, "Second line")
-}