From f8a1fdf4c63fc01533614dc9c92df595862e387c Mon Sep 17 00:00:00 2001 From: Soam Vasani Date: Wed, 2 Nov 2016 15:06:55 -0700 Subject: [PATCH] Improve logging in controller, fetcher, poolmgr TODO: most of these should be in a debug loglevel. --- controller/environmentApi.go | 2 ++ environments/fetcher/fetcher.go | 9 ++++++++- poolmgr/api.go | 7 +++++++ poolmgr/gp.go | 10 +++++++++- 4 files changed, 26 insertions(+), 2 deletions(-) diff --git a/controller/environmentApi.go b/controller/environmentApi.go index 57ca0287..ac2835be 100644 --- a/controller/environmentApi.go +++ b/controller/environmentApi.go @@ -48,10 +48,12 @@ func (api *API) EnvironmentApiCreate(w http.ResponseWriter, r *http.Request) { if err != nil { api.respondWithError(w, err) } + defer r.Body.Close() var env fission.Environment err = json.Unmarshal(body, &env) if err != nil { + log.Printf("Failed to unmarshal request body: [%v]", body) api.respondWithError(w, err) return } diff --git a/environments/fetcher/fetcher.go b/environments/fetcher/fetcher.go index d873d943..1f8b6829 100644 --- a/environments/fetcher/fetcher.go +++ b/environments/fetcher/fetcher.go @@ -32,20 +32,24 @@ func (fetcher *Fetcher) handler(w http.ResponseWriter, r *http.Request) { // parse request body, err := ioutil.ReadAll(r.Body) if err != nil { + log.Printf("Error reading request body") http.Error(w, err.Error(), 500) return } - req := FetchRequest{} + var req FetchRequest err = json.Unmarshal(body, &req) if err != nil { + log.Printf("Error reading request body: %v", err) http.Error(w, err.Error(), 500) return } + log.Printf("fetcher request: %v", req) // fetch the file and save it to tmp path resp, err := http.Get(req.Url) if err != nil { e := fmt.Sprintf("Failed to fetch from url: %v", err) + log.Printf(e) http.Error(w, e, 400) return } @@ -53,6 +57,7 @@ func (fetcher *Fetcher) handler(w http.ResponseWriter, r *http.Request) { body, err = ioutil.ReadAll(resp.Body) if err != nil { e := fmt.Sprintf("Failed to read from url: %v", err) + log.Printf(e) http.Error(w, e, 400) return } @@ -61,6 +66,7 @@ func (fetcher *Fetcher) handler(w http.ResponseWriter, r *http.Request) { err = ioutil.WriteFile(tmpPath, body, 0600) if err != nil { e := fmt.Sprintf("Failed to write file: %v", err) + log.Printf(e) http.Error(w, e, 500) return } @@ -71,6 +77,7 @@ func (fetcher *Fetcher) handler(w http.ResponseWriter, r *http.Request) { err = os.Rename(tmpPath, filepath.Join(fetcher.sharedVolumePath, req.Filename)) if err != nil { e := fmt.Sprintf("Failed to move file: %v", err) + log.Printf(e) http.Error(w, e, 500) return } diff --git a/poolmgr/api.go b/poolmgr/api.go index 7928168f..9206cc92 100644 --- a/poolmgr/api.go +++ b/poolmgr/api.go @@ -94,12 +94,14 @@ func (api *API) getFunctionEnv(m *fission.Metadata) (*fission.Environment, error } // Cache miss -- get func from controller + log.Printf("[%v] getting function from controller", m) f, err := api.controller.FunctionGet(m) if err != nil { return nil, err } // Get env from metadata + log.Printf("[%v] getting env from controller", m) env, err = api.controller.EnvironmentGet(&f.Environment) if err != nil { return nil, err @@ -113,6 +115,7 @@ func (api *API) getFunctionEnv(m *fission.Metadata) (*fission.Environment, error func (api *API) getServiceForFunction(m *fission.Metadata) (string, error) { // Check function -> svc map + log.Printf("[%v] Checking for cached function service", m.Name) result, err := api.functionService.Get(m) if err == nil { // Ok: return svc name @@ -121,20 +124,24 @@ func (api *API) getServiceForFunction(m *fission.Metadata) (string, error) { } // None exists, so create a new funcSvc: + log.Printf("[%v] No cached function service found, creating one", m.Name) // from Func -> get Env + log.Printf("[%v] getting environment for function", m.Name) env, err := api.getFunctionEnv(m) if err != nil { return "", err } // from Env -> get GenericPool + log.Printf("[%v] getting generic pool for env", m.Name) pool, err := api.poolMgr.GetPool(env) if err != nil { return "", err } // from GenericPool -> get one function container + log.Printf("[%v] getting function service from pool", m.Name) funcSvc, err := pool.GetFuncSvc(m) if err != nil { return "", err diff --git a/poolmgr/gp.go b/poolmgr/gp.go index cb1919ee..2d5410f2 100644 --- a/poolmgr/gp.go +++ b/poolmgr/gp.go @@ -65,6 +65,7 @@ func MakeGenericPool( initialReplicas int32, namespace string) (*GenericPool, error) { + log.Printf("Creating pool for environment %v", env.Metadata) gp := &GenericPool{ env: env, replicas: initialReplicas, @@ -82,6 +83,7 @@ func MakeGenericPool( } // wait for at least one pod to be ready + log.Printf("[%v] Deployment created, waiting for a ready pod", env.Metadata) err = gp.waitForReadyPod() if err != nil { return nil, err @@ -124,6 +126,7 @@ func (gp *GenericPool) _choosePod(newLabels map[string]string) (*v1.Pod, error) for { // Retries took too long, error out. if time.Now().Sub(startTime) > gp.podReadyTimeout { + log.Printf("[%v] Erroring out, timed out", newLabels) return nil, errors.New("timeout: waited too long to get a ready pod") } @@ -146,6 +149,8 @@ func (gp *GenericPool) _choosePod(newLabels map[string]string) (*v1.Pod, error) readyPods = append(readyPods, pod) } } + log.Printf("[%v] found %v ready pods of %v total", + newLabels, len(readyPods), len(podList.Items)) // If there are no ready pods, wait and retry. if len(readyPods) == 0 { @@ -170,7 +175,7 @@ func (gp *GenericPool) _choosePod(newLabels map[string]string) (*v1.Pod, error) log.Printf("failed to relabel pod: %v", err) continue } - log.Printf("Chose a pod: %v", chosenPod.ObjectMeta.Name) + log.Printf("Chosen pod: %v (in %v)", chosenPod.ObjectMeta.Name, time.Now().Sub(startTime)) return &chosenPod, nil } } @@ -188,6 +193,7 @@ func labelsForMetadata(metadata *fission.Metadata) map[string]string { func (gp *GenericPool) specializePod(metadata *fission.Metadata) (*v1.Pod, error) { newLabels := labelsForMetadata(metadata) + log.Printf("[%v] Choosing pod from pool", metadata) pod, err := gp.choosePod(newLabels) if err != nil { return nil, err @@ -205,6 +211,7 @@ func (gp *GenericPool) specializePod(metadata *fission.Metadata) (*v1.Pod, error gp.controllerUrl, metadata.Name, metadata.Uid) fetcherRequest := fmt.Sprintf("{\"url\": \"%v\", \"filename\": \"user\"}", functionUrl) + log.Printf("[%v] calling fetcher to copy function", metadata) resp, err := http.Post(fetcherUrl, "application/json", bytes.NewReader([]byte(fetcherRequest))) if err != nil { return nil, err @@ -215,6 +222,7 @@ func (gp *GenericPool) specializePod(metadata *fission.Metadata) (*v1.Pod, error } // get function run container to specialize + log.Printf("[%v] specializing pod", metadata) specializeUrl := fmt.Sprintf("http://%v:8888/specialize", podIP) resp2, err := http.Post(specializeUrl, "", bytes.NewReader([]byte{})) if err != nil {