Improve logging in controller, fetcher, poolmgr

TODO: most of these should be in a debug loglevel.

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
 	}

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
 	}

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

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 {