diff --git a/api/logs/mock.go b/api/logs/mock.go index 6d10eb557..5aa99a758 100644 --- a/api/logs/mock.go +++ b/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 - return nil + bytes, err := ioutil.ReadAll(callLog) + m.Logs[callID] = bytes + return err } func (m *mock) GetLog(ctx context.Context, appName, callID string) (io.Reader, error) { - logEntry := m.Logs[callID] - if logEntry == nil { + logEntry, ok := m.Logs[callID] + if !ok { return nil, models.ErrCallLogNotFound } - - return logEntry, nil + return bytes.NewReader(logEntry), nil } diff --git a/api/server/runner_test.go b/api/server/runner_test.go index b5b784b22..0d3403876 100644 --- a/api/server/runner_test.go +++ b/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{}, fnl, rnr, ServerTypeFull) + srv := testServer(ds, &mqs.Mock{}, ds, 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 - body string - method string - expectedCode int - expectedHeaders map[string][]string - expectedErrSubStr string + path string + body string + method string + expectedCode int + expectedHeaders map[string][]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/myhotjason", respTypeLie, "GET", http.StatusOK, expCTHeaders, ""}, - {"/r/myapp/myhotjason", respTypeJason, "GET", http.StatusOK, expCTHeaders, ""}, + {"/r/myapp/myhot", respTypeLie, "GET", http.StatusOK, expCTHeaders, "", nil}, + {"/r/myapp/myhotjason", respTypeLie, "GET", http.StatusOK, expCTHeaders, "", nil}, + {"/r/myapp/myhotjason", respTypeJason, "GET", http.StatusOK, expCTHeaders, "", nil}, - {"/r/myapp/myhot", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid http response"}, - {"/r/myapp/myhotjason", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid json response"}, + {"/r/myapp/myhot", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid http response", nil}, + {"/r/myapp/myhotjason", badHot, "GET", http.StatusBadGateway, expHeaders, "invalid json response", nil}, - {"/r/myapp/myroute", ok, "GET", http.StatusOK, expHeaders, ""}, - {"/r/myapp/myerror", crasher, "GET", http.StatusBadGateway, expHeaders, "container exit code 2"}, - {"/r/myapp/mydne", ``, "GET", http.StatusNotFound, nil, "pull access denied"}, - {"/r/myapp/mydnehot", ``, "GET", http.StatusNotFound, nil, "pull access denied"}, + {"/r/myapp/myroute", ok, "GET", http.StatusOK, expHeaders, "", nil}, + {"/r/myapp/myerror", crasher, "GET", http.StatusBadGateway, expHeaders, "container exit code 2", nil}, + {"/r/myapp/mydne", ``, "GET", http.StatusNotFound, nil, "pull access denied", nil}, + {"/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) - if maxLog > 1024 { - maxLog = 1024 + maxBody := len(respBody) + if maxBody > 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]) + } + } + } + } + } } } diff --git a/images/fn-test-utils/fn-test-utils.go b/images/fn-test-utils/fn-test-utils.go index 0635cfcff..fb2b7b615 100644 --- a/images/fn-test-utils/fn-test-utils.go +++ b/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 - ResponseSize int `json:"responseSize,omitempty"` + // duplicate trailer if > 0 + 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) - if err != nil { - return err - } - if len(b) > responseSize { - responseSize = len(b) - } - b = b[:responseSize] - out.Write(b) - } else { - json.NewEncoder(out).Encode(jsonResponse) + b, err := json.Marshal(jsonResponse) + if err != nil { + log.Printf("json marshal error %v", err) + return err + } + + _, err = out.Write(b) + if err != nil { + log.Printf("json write error %v", err) + return err } 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 { - - var buf bytes.Buffer - bufWriter := bufio.NewWriter(&buf) - - 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) + err = hResp.Write(out) + if err != nil { + log.Printf("http response write error %v", err) + return err } return nil diff --git a/test/fn-api-tests/exec_test.go b/test/fn-api-tests/exec_test.go index 4c665dd82..2dd6ae614 100644 --- a/test/fn-api-tests/exec_test.go +++ b/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() diff --git a/test/fn-api-tests/fn/multi-log/Dockerfile b/test/fn-api-tests/fn/multi-log/Dockerfile deleted file mode 100644 index 1c1b324fd..000000000 --- a/test/fn-api-tests/fn/multi-log/Dockerfile +++ /dev/null @@ -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"] diff --git a/test/fn-api-tests/fn/multi-log/func.yaml b/test/fn-api-tests/fn/multi-log/func.yaml deleted file mode 100644 index 2da938b93..000000000 --- a/test/fn-api-tests/fn/multi-log/func.yaml +++ /dev/null @@ -1,5 +0,0 @@ -name: fnproject/multi-log -version: 0.0.1 -runtime: go -entrypoint: ./func -path: /multi-log diff --git a/test/fn-api-tests/fn/multi-log/main.go b/test/fn-api-tests/fn/multi-log/main.go deleted file mode 100644 index a8f813921..000000000 --- a/test/fn-api-tests/fn/multi-log/main.go +++ /dev/null @@ -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") -}