Nail/fission-src
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Change log-level for better performance and less annoying logs (#1231)

Browse Source 
This PR removes not so useful logs and changes most of Info level
log to Debug/Error level in hot path while preserving some of them
that is helpful for troubleshooting.
This commit is contained in:
Ta-Ching Chen
2019-07-19 12:38:36 +08:00
committed by GitHub
parent 6e00733f68
commit 1beaa9ec13
23 changed files with 98 additions and 164 deletions
Download Patch File Download Diff File Expand all files Collapse all files
pkg/executor/api.go
+11 -10
View File
@@ -24,7 +24,6 @@ import (
"net/http"
"strings"
"github.com/fission/fission/pkg/utils"
"github.com/gorilla/mux"
"go.opencensus.io/plugin/ochttp"
"go.uber.org/zap"
@@ -73,16 +72,17 @@ func (executor *Executor) getServiceForFunctionApi(w http.ResponseWriter, r *htt
// invalidates the cache entry if the pod address was cached.
func (executor *Executor) getServiceForFunction(ctx context.Context, m *metav1.ObjectMeta) (string, error) {
// Check function -> svc cache
executor.logger.Info("checking for cached function service",
executor.logger.Debug("checking for cached function service",
zap.String("function_name", m.Name),
zap.String("function_namespace", m.Namespace))
fsvc, err := executor.fsCache.GetByFunction(m)
if err == nil {
if executor.isValidAddress(fsvc) {
// Cached, return svc address
return fsvc.Address, nil
} else {
executor.logger.Info("deleting cache entry for invalid address",
executor.logger.Debug("deleting cache entry for invalid address",
zap.String("function_name", m.Name),
zap.String("function_namespace", m.Namespace),
zap.String("address", fsvc.Address))
@@ -131,20 +131,21 @@ func (executor *Executor) healthHandler(w http.ResponseWriter, r *http.Request)
}
func (executor *Executor) Serve(port int) {
r := mux.NewRouter()
r.HandleFunc("/v2/getServiceForFunction", executor.getServiceForFunctionApi).Methods("POST")
r.HandleFunc("/v2/tapService", executor.tapService).Methods("POST")
r.HandleFunc("/healthz", executor.healthHandler).Methods("GET")
address := fmt.Sprintf(":%v", port)
executor.logger.Info("starting executor", zap.Int("port", port))
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
executor.ndm.Run(ctx)
executor.gpm.Run(ctx)
r.Use(utils.LoggingMiddleware(executor.logger))
r := mux.NewRouter()
r.HandleFunc("/v2/getServiceForFunction", executor.getServiceForFunctionApi).Methods("POST")
r.HandleFunc("/v2/tapService", executor.tapService).Methods("POST")
r.HandleFunc("/healthz", executor.healthHandler).Methods("GET")
address := fmt.Sprintf(":%v", port)
err := http.ListenAndServe(address, &ochttp.Handler{
Handler: r,
// Propagation: &b3.HTTPFormat{},
})
executor.logger.Fatal("done listening", zap.Error(err))
}
pkg/executor/executor.go
+2 -6
View File
@@ -37,7 +37,6 @@ import (
"github.com/fission/fission/pkg/executor/poolmgr"
"github.com/fission/fission/pkg/executor/reaper"
fetcherConfig "github.com/fission/fission/pkg/fetcher/config"
"github.com/fission/fission/pkg/utils"
)
type (
@@ -115,7 +114,7 @@ func (executor *Executor) serveCreateFuncServices() {
} else {
// There's an existing request for this function, wait for it to finish
go func() {
executor.logger.Info("waiting for concurrent request for the same function",
executor.logger.Debug("waiting for concurrent request for the same function",
zap.Any("function", m))
wg.Wait()
@@ -147,7 +146,7 @@ func (executor *Executor) getFunctionExecutorType(meta *metav1.ObjectMeta) (fv1.
}
func (executor *Executor) createServiceForFunction(ctx context.Context, meta *metav1.ObjectMeta) (*fscache.FuncSvc, error) {
executor.logger.Info("no cached function service found, creating one",
executor.logger.Debug("no cached function service found, creating one",
zap.String("function_name", meta.Name),
zap.String("function_namespace", meta.Namespace))
@@ -206,9 +205,6 @@ func serveMetric(logger *zap.Logger) {
// StartExecutor Starts executor and the executor components such as Poolmgr,
// deploymgr and potential future executor types
func StartExecutor(logger *zap.Logger, fissionNamespace string, functionNamespace string, envBuilderNamespace string, port int) error {
// setup a signal handler for SIGTERM
utils.SetupStackTraceHandler()
fissionClient, kubernetesClient, _, err := crd.MakeFissionClient()
err = fissionClient.WaitForCRDs()
pkg/executor/newdeploy/newdeploymgr.go
+4 -6
View File
@@ -84,9 +84,6 @@ func MakeNewDeploy(
fetcherConfig *fetcherConfig.Config,
instanceID string,
) *NewDeploy {
logger.Info("creating NewDeploy ExecutorType")
enableIstio := false
if len(os.Getenv("ENABLE_ISTIO")) > 0 {
istio, err := strconv.ParseBool(os.Getenv("ENABLE_ISTIO"))
@@ -183,7 +180,7 @@ func (deploy *NewDeploy) initEnvController() (k8sCache.Store, k8sCache.Controlle
oldEnv := oldObj.(*fv1.Environment)
// Currently only an image update in environment calls for function's deployment recreation. In future there might be more attributes which would want to do it
if oldEnv.Spec.Runtime.Image != newEnv.Spec.Runtime.Image {
deploy.logger.Info("Updating all function of the environment that changed, old env:", zap.Any("environment", oldEnv))
deploy.logger.Debug("Updating all function of the environment that changed, old env:", zap.Any("environment", oldEnv))
funcs := deploy.getEnvFunctions(&newEnv.Metadata)
for _, f := range funcs {
function, err := deploy.fissionClient.Functions(f.Metadata.Namespace).Get(f.Metadata.Name)
@@ -495,7 +492,8 @@ func (deploy *NewDeploy) updateFuncDeployment(fn *fv1.Function, env *fv1.Environ
fnObjName := fsvc.Name
deployLabels := deploy.getDeployLabels(fn, env)
deploy.logger.Info("updating deployment due to function/environment update", zap.String("deployment", fnObjName), zap.Any("function", fn.Metadata.Name))
deploy.logger.Info("updating deployment due to function/environment update",
zap.String("deployment", fnObjName), zap.Any("function", fn.Metadata.Name))
newDeployment, err := deploy.getDeploymentSpec(fn, env, fnObjName, deployLabels)
if err != nil {
@@ -589,7 +587,7 @@ func (deploy *NewDeploy) updateKubeObjRefRV(fsvc *fscache.FuncSvc, objKind strin
// updateStatus is a function which updates status of update.
// Current implementation only logs messages, in future it will update function status
func (deploy *NewDeploy) updateStatus(fn *fv1.Function, err error, message string) {
deploy.logger.Info("function status update", zap.Error(err), zap.Any("function", fn), zap.String("message", message))
deploy.logger.Error("function status update", zap.Error(err), zap.Any("function", fn), zap.String("message", message))
}
// IsValid does a get on the service address to ensure it's a valid service, then
pkg/executor/poolmgr/funcwatcher.go
+2 -2
View File
@@ -78,7 +78,7 @@ func (gpm *GenericPoolManager) makeFuncController(fissionClient *crd.FissionClie
if err != nil {
gpm.logger.Error("error creating rolebinding", zap.Error(err), zap.String("role_binding", types.SecretConfigMapGetterRB))
} else {
gpm.logger.Info("successfully set up rolebinding for fetcher service account for function",
gpm.logger.Debug("successfully set up rolebinding for fetcher service account for function",
zap.String("service_account", types.FissionFetcherSA),
zap.String("service_account_namepsace", envNs),
zap.String("function_name", fn.Metadata.Name),
@@ -194,7 +194,7 @@ func (gpm *GenericPoolManager) makeFuncController(fissionClient *crd.FissionClie
if err != nil {
gpm.logger.Error("error creating rolebinding", zap.Error(err), zap.String("role_binding", types.SecretConfigMapGetterRB))
} else {
gpm.logger.Info("successfully set up rolebinding for fetcher service account for function",
gpm.logger.Debug("successfully set up rolebinding for fetcher service account for function",
zap.String("service_account", types.FissionFetcherSA),
zap.String("service_account_namepsace", envNs),
zap.String("function_name", newFunc.Metadata.Name),
pkg/executor/poolmgr/gp.go
+9 -3
View File
@@ -234,14 +234,14 @@ func (gp *GenericPool) _choosePod(newLabels map[string]string) (*apiv1.Pod, erro
// modified, this should fail; in that case just
// retry.
chosenPod.ObjectMeta.Labels = newLabels
gp.logger.Info("relabeling pod", zap.String("pod", chosenPod.ObjectMeta.Name))
_, err = gp.kubernetesClient.CoreV1().Pods(gp.namespace).Update(chosenPod)
if err != nil {
gp.logger.Error("failed to relabel pod", zap.Error(err), zap.String("pod", chosenPod.ObjectMeta.Name))
continue
}
}
gp.logger.Info("chose pod", zap.String("pod", chosenPod.ObjectMeta.Name), zap.Duration("elapsed_time", time.Since(startTime)))
gp.logger.Info("chose pod", zap.Any("labels", newLabels),
zap.String("pod", chosenPod.ObjectMeta.Name), zap.Duration("elapsed_time", time.Since(startTime)))
return chosenPod, nil
}
}
@@ -587,10 +587,16 @@ func (gp *GenericPool) GetFuncSvc(ctx context.Context, m *metav1.ObjectMeta) (*f
svc := utils.GetFunctionIstioServiceName(m.Name, m.Namespace)
svcHost = fmt.Sprintf("%v.%v:8888", svc, gp.namespace)
} else {
gp.logger.Info("using pod IP for specialized pod", zap.String("pod", pod.ObjectMeta.Name), zap.String("function", m.Name))
svcHost = fmt.Sprintf("%v:8888", pod.Status.PodIP)
}
gp.logger.Info("specialized pod",
zap.String("pod", pod.ObjectMeta.Name),
zap.String("podNamespace", pod.ObjectMeta.Namespace),
zap.String("function", m.Name),
zap.String("functionNamespace", m.Namespace),
zap.String("specialization_host", svcHost))
kubeObjRefs := []apiv1.ObjectReference{
{
Kind: "pod",
pkg/executor/poolmgr/gpm.go
+4 -5
View File
@@ -111,7 +111,7 @@ func MakeGenericPoolManager(
if len(os.Getenv("ENABLE_ISTIO")) > 0 {
istio, err := strconv.ParseBool(os.Getenv("ENABLE_ISTIO"))
if err != nil {
gpmLogger.Info("failed to parse ENABLE_ISTIO")
gpmLogger.Error("failed to parse 'ENABLE_ISTIO', set to false", zap.Error(err))
}
gpm.enableIstio = istio
}
@@ -204,7 +204,7 @@ func (gpm *GenericPoolManager) CleanupPools(envs []fv1.Environment) {
func (gpm *GenericPoolManager) GetFuncSvc(ctx context.Context, metadata *metav1.ObjectMeta) (*fscache.FuncSvc, error) {
// from Func -> get Env
gpm.logger.Info("getting environment for function", zap.String("function", metadata.Name))
gpm.logger.Debug("getting environment for function", zap.String("function", metadata.Name))
env, err := gpm.getFunctionEnv(metadata)
if err != nil {
return nil, err
@@ -216,7 +216,7 @@ func (gpm *GenericPoolManager) GetFuncSvc(ctx context.Context, metadata *metav1.
}
// from GenericPool -> get one function container
// (this also adds to the cache)
gpm.logger.Info("getting function service from pool", zap.String("function", metadata.Name))
gpm.logger.Debug("getting function service from pool", zap.String("function", metadata.Name))
return pool.GetFuncSvc(ctx, metadata)
}
@@ -237,7 +237,6 @@ func (gpm *GenericPoolManager) getFunctionEnv(m *metav1.ObjectMeta) (*fv1.Enviro
}
// Get env from metadata
gpm.logger.Info("getting env", zap.Any("function", m))
env, err = gpm.fissionClient.Environments(f.Spec.Environment.Namespace).Get(f.Spec.Environment.Name)
if err != nil {
return nil, err
@@ -347,7 +346,7 @@ func (gpm *GenericPoolManager) idleObjectReaper() {
// For function with the environment that no longer exists, executor
// cleanups the idle pod as usual and prints log to notify user.
if _, ok := envList[fsvc.Environment.Metadata.UID]; !ok {
gpm.logger.Info("function environment no longer exists",
gpm.logger.Warn("function environment no longer exists",
zap.String("environment", fsvc.Environment.Metadata.Name),
zap.String("function", fsvc.Name))
}
pkg/executor/reaper/reaper.go
+7 -9
View File
@@ -122,7 +122,7 @@ func cleanupDeployments(logger *zap.Logger, client *kubernetes.Clientset, instan
for _, dep := range deploymentList.Items {
id, ok := dep.ObjectMeta.Labels[types.EXECUTOR_INSTANCEID_LABEL]
if ok && id != instanceId {
logger.Info("cleaning up deployment", zap.String("deployment", dep.ObjectMeta.Name))
logger.Debug("cleaning up deployment", zap.String("deployment", dep.ObjectMeta.Name))
err := client.ExtensionsV1beta1().Deployments(dep.ObjectMeta.Namespace).Delete(dep.ObjectMeta.Name, &delOpt)
if err != nil {
logger.Error("error cleaning up deployment",
@@ -135,7 +135,7 @@ func cleanupDeployments(logger *zap.Logger, client *kubernetes.Clientset, instan
// Backward compatibility with older label name
pid, pok := dep.ObjectMeta.Labels[types.POOLMGR_INSTANCEID_LABEL]
if pok && pid != instanceId {
logger.Info("cleaning up deployment", zap.String("deployment", dep.ObjectMeta.Name))
logger.Debug("cleaning up deployment", zap.String("deployment", dep.ObjectMeta.Name))
err := client.ExtensionsV1beta1().Deployments(dep.ObjectMeta.Namespace).Delete(dep.ObjectMeta.Name, &delOpt)
if err != nil {
logger.Error("error cleaning up deployment",
@@ -157,7 +157,7 @@ func cleanupPods(logger *zap.Logger, client *kubernetes.Clientset, instanceId st
for _, pod := range podList.Items {
id, ok := pod.ObjectMeta.Labels[types.EXECUTOR_INSTANCEID_LABEL]
if ok && id != instanceId {
logger.Info("cleaning up pod", zap.String("pod", pod.ObjectMeta.Name))
logger.Debug("cleaning up pod", zap.String("pod", pod.ObjectMeta.Name))
err := client.CoreV1().Pods(pod.ObjectMeta.Namespace).Delete(pod.ObjectMeta.Name, nil)
if err != nil {
logger.Error("error cleaning up pod",
@@ -170,7 +170,7 @@ func cleanupPods(logger *zap.Logger, client *kubernetes.Clientset, instanceId st
// Backward compatibility with older label name
pid, pok := pod.ObjectMeta.Labels[types.POOLMGR_INSTANCEID_LABEL]
if pok && pid != instanceId {
logger.Info("cleaning up pod", zap.String("pod", pod.ObjectMeta.Name))
logger.Debug("cleaning up pod", zap.String("pod", pod.ObjectMeta.Name))
err := client.CoreV1().Pods(pod.ObjectMeta.Namespace).Delete(pod.ObjectMeta.Name, nil)
if err != nil {
logger.Error("error cleaning up pod",
@@ -178,9 +178,7 @@ func cleanupPods(logger *zap.Logger, client *kubernetes.Clientset, instanceId st
zap.String("pod_name", pod.ObjectMeta.Name),
zap.String("pod_namespace", pod.ObjectMeta.Namespace))
}
// ignore err
}
}
return nil
}
@@ -193,7 +191,7 @@ func cleanupServices(logger *zap.Logger, client *kubernetes.Clientset, instanceI
for _, svc := range svcList.Items {
id, ok := svc.ObjectMeta.Labels[types.EXECUTOR_INSTANCEID_LABEL]
if ok && id != instanceId {
logger.Info("cleaning up service", zap.String("service", svc.ObjectMeta.Name))
logger.Debug("cleaning up service", zap.String("service", svc.ObjectMeta.Name))
err := client.CoreV1().Services(svc.ObjectMeta.Namespace).Delete(svc.ObjectMeta.Name, nil)
if err != nil {
logger.Error("error cleaning up service",
@@ -216,7 +214,7 @@ func cleanupHpa(logger *zap.Logger, client *kubernetes.Clientset, instanceId str
for _, hpa := range hpaList.Items {
id, ok := hpa.ObjectMeta.Labels[types.EXECUTOR_INSTANCEID_LABEL]
if ok && id != instanceId {
logger.Info("cleaning up HPA", zap.String("hpa", hpa.ObjectMeta.Name))
logger.Debug("cleaning up HPA", zap.String("hpa", hpa.ObjectMeta.Name))
err := client.AutoscalingV1().HorizontalPodAutoscalers(hpa.ObjectMeta.Namespace).Delete(hpa.ObjectMeta.Name, nil)
if err != nil {
logger.Error("error cleaning up HPA",
@@ -236,7 +234,7 @@ func cleanupHpa(logger *zap.Logger, client *kubernetes.Clientset, instanceId str
// deletes the rolebindings completely if there are no Service Accounts in a rolebinding object.
func CleanupRoleBindings(logger *zap.Logger, client *kubernetes.Clientset, fissionClient *crd.FissionClient, functionNs, envBuilderNs string, cleanupRoleBindingInterval time.Duration) {
for {
logger.Info("starting cleanupRoleBindings cycle")
logger.Debug("starting cleanupRoleBindings cycle")
// get all rolebindings ( just to be efficient, one call to kubernetes )
rbList, err := client.RbacV1beta1().RoleBindings(meta_v1.NamespaceAll).List(meta_v1.ListOptions{})
if err != nil {