Merge pull request #5 from Spellchaser/log_improvements

Log improvements

chaos/chaos.go

@@ -66,13 +66,13 @@ func (c *Chaos) Execute(resultchan chan<- *ChaosResult) {
 		return
 	}
 	if !enrolled {
-		resultchan <- c.NewResult(fmt.Errorf("Deployment %s is no longer enrolled in kube-monkey. Skipping\n", c.deployment.Name()))
+		resultchan <- c.NewResult(fmt.Errorf("Skipping deployment %s; reason=no longer enrolled", c.deployment.Name()))
 		return
 	}
 
 	// Has deployment been blacklisted since scheduling?
 	if c.deployment.IsBlacklisted(config.BlacklistedNamespaces()) {
-		resultchan <- c.NewResult(fmt.Errorf("Deployment %s is blacklisted. Skipping\n", c.deployment.Name()))
+		resultchan <- c.NewResult(fmt.Errorf("Skipping deployment %s; reason=blacklisted", c.deployment.Name()))
 		return
 	}
 
@@ -110,14 +110,14 @@ func (c *Chaos) Terminate(client *kube.Clientset) error {
 
 	targetPod := RandomPodName(pods)
 
-	glog.Errorf("Terminating pod %s for deployment %s\n", targetPod, c.deployment.Name())
+	glog.V(2).Infof("Terminating pod %s for deployment %s", targetPod, c.deployment.Name())
 	return c.DeletePod(client, targetPod)
 }
 
 // Terminates ALL pods for the deployment
 // Not the default, or recommended, behavior
 func (c *Chaos) TerminateAll(client *kube.Clientset) error {
-	glog.V(1).Infof("Terminating ALL pods for deployment %s\n", c.deployment.Name())
+	glog.V(2).Infof("Terminating ALL pods for deployment %s", c.deployment.Name())
 
 	pods, err := c.deployment.Pods(client)
 	if err != nil {
@@ -141,7 +141,7 @@ func (c *Chaos) TerminateAll(client *kube.Clientset) error {
 // Deletes a pod for a deployment
 func (c *Chaos) DeletePod(client *kube.Clientset, podName string) error {
 	if config.DryRun() {
-		glog.V(1).Infof("[DryRun Mode] Terminated pod %s for deployment %s\n", podName, c.deployment.Name())
+		glog.V(2).Infof("[DryRun Mode] Terminated pod %s for deployment %s", podName, c.deployment.Name())
 		return nil
 	} else {
 		return c.deployment.DeletePod(client, podName)

config/config.go

@@ -49,7 +49,7 @@ func setupWatch() {
 	// TODO: This does not appear to be working
 	viper.WatchConfig()
 	viper.OnConfigChange(func(e fsnotify.Event) {
-		glog.V(2).Infoln("Config change detected")
+		glog.V(4).Info("Config change detected")
 		ValidateConfigs()
 	})
 }
@@ -68,7 +68,7 @@ func Init() error {
 		glog.Errorf("Failed to validate %v", err)
 		return err
 	} else {
-		glog.V(3).Info("Successfully validated configs")
+		glog.V(4).Info("Successfully validated configs")
 	}
 	setupWatch()
 	return nil

deployments/eligible_deployments.go

@@ -25,7 +25,7 @@ func EligibleDeployments() ([]*Deployment, error) {
 	for _, dep := range enabledDeployments {
 		deployment, err := New(&dep)
 		if err != nil {
-			glog.V(3).Infof("Skipping eligible deployment %s because of error:\n%s\n", dep.Name, err.Error())
+			glog.V(1).Infof("Skipping eligible deployment %s because of error:\n%s\n", dep.Name, err.Error())
 			continue
 		}
 

kubemonkey/kubemonkey.go

@@ -1,6 +1,7 @@
 package kubemonkey
 
 import (
+	"fmt"
 	"time"
 
 	"github.com/golang/glog"
@@ -19,11 +20,12 @@ func verifyKubeClient() error {
 func durationToNextRun(runhour int, location *time.Location) time.Duration {
 	if config.DebugEnabled() {
 		debugDelayDuration := config.DebugScheduleDelay()
-		glog.V(2).Infof("Debug mode detected! Generating next schedule in %.0f sec\n", debugDelayDuration.Seconds())
+		glog.V(1).Infof("Debug mode detected!")
+		glog.V(1).Infof("Status Update: Generating next schedule in %.0f sec\n", debugDelayDuration.Seconds())
 		return debugDelayDuration
 	} else {
 		nextRun := calendar.NextRuntime(location, runhour)
-		glog.V(2).Infof("Generating next schedule at %s\n", nextRun)
+		glog.V(1).Infof("Status Update: Generating next schedule at %s\n", nextRun)
 		return nextRun.Sub(time.Now())
 	}
 }
@@ -45,6 +47,7 @@ func Run() error {
 			glog.Fatal(err.Error())
 		}
 		schedule.Print()
+		fmt.Println(schedule)
 		ScheduleTerminations(schedule.Entries())
 	}
 }
@@ -61,7 +64,7 @@ func ScheduleTerminations(entries []*chaos.Chaos) {
 	completedCount := 0
 	var result *chaos.ChaosResult
 
-	glog.V(3).Infof("Waiting for terminations to run")
+	glog.V(3).Infof("Status Update: Waiting to run scheduled terminations.")
 
 	// Gather results
 	for completedCount < len(entries) {
@@ -72,7 +75,8 @@ func ScheduleTerminations(entries []*chaos.Chaos) {
 			glog.V(2).Infof("Termination successfully executed for deployment %s\n", result.Deployment().Name())
 		}
 		completedCount++
+		glog.V(4).Info("Status Update: ", len(entries) - completedCount, " scheduled terminations left.")
 	}
 
-	glog.V(3).Info("All terminations done")
+	glog.V(3).Info("Status Update: All terminations done.")
 }

kubernetes/kubernetes.go

@@ -61,6 +61,11 @@ func NewInClusterClient() (*kube.Clientset, error) {
 		return nil, err
 	}
 
+	if apiserverHost, override := cfg.ClusterAPIServerHost(); override {
+		glog.V(4).Infof("API server host overriden to: %s\n", apiserverHost)
+		config.Host = apiserverHost
+	}
+
 	clientset, err := kube.NewForConfig(config)
 	if err != nil {
 		glog.Errorf("failed to create clientset in NewForConfig: %v", err)

main.go

@@ -28,7 +28,7 @@ func initLogging() {
 		if (err != nil) {
 			glog.Errorf("Failed to open custom log directory; defaulting to /tmp! Error: %v", flag.Lookup("log_dir").Value, err)
 		} else {
-			glog.V(8).Infof("Created custom logging %s directory!", flag.Lookup("log_dir").Value)
+			glog.V(5).Infof("Created custom logging %s directory!", flag.Lookup("log_dir").Value)
 		}
 	}
 	// Since km runs as a k8 pod, log everything to stderr (stdout not supported)
@@ -49,7 +49,7 @@ func main() {
 	// Initialize configs
 	initConfig()
 
-	glog.Infof("Starting kube-monkey with v logging level %v and local log directory %s", flag.Lookup("v").Value, flag.Lookup("log_dir").Value)
+	glog.V(1).Infof("Starting kube-monkey with v logging level %v and local log directory %s", flag.Lookup("v").Value, flag.Lookup("log_dir").Value)
 
 	if err := kubemonkey.Run(); err != nil {
 		glog.Fatal(err.Error())

schedule/schedule.go

@@ -1,7 +1,9 @@
 package schedule
 
 import (
+	"fmt"
 	"time"
+	"strings"
 	"math/rand"
 
 	"github.com/golang/glog"
@@ -24,23 +26,32 @@ func (s *Schedule) Add(entry *chaos.Chaos) {
 	s.entries = append(s.entries, entry)
 }
 
-func (s *Schedule) Print() {
-	glog.V(3).Info("\t********** Today's schedule **********")
+func (s *Schedule) String() string {
+	schedString := []string{}
+	schedString = append(schedString, fmt.Sprint("\t********** Today's schedule **********"))
 	if len(s.entries) == 0 {
-		glog.V(3).Info("No terminations scheduled")
+		schedString = append(schedString, fmt.Sprint("No terminations scheduled"))
 	} else {
-		glog.V(3).Info("\tDeployment\t\tTermination time\n")
-		glog.V(3).Info("\t----------\t\t----------------\n")
+		schedString = append(schedString, fmt.Sprint("\tDeployment\t\t\tTermination time"))
+		schedString = append(schedString, fmt.Sprint("\t----------\t\t\t----------------"))
 		for _, chaos := range s.entries {
-			glog.V(3).Infof("\t%s\t\t%s\n", chaos.Deployment().Name(), chaos.KillAt())
+			schedString = append(schedString, fmt.Sprintf("\t%s\t\t\t%s", chaos.Deployment().Name(), chaos.KillAt().Format("01/01/2017 18:42:05 Z0700 UTC")))
 		}
 	}
+	schedString = append(schedString, fmt.Sprint("\t********** End of schedule **********"))
 
-	glog.V(3).Info("\t********** End of schedule **********")
+	return strings.Join(schedString, "\n")
+}
+
+func (s Schedule) Print() {
+	glog.V(4).Infof("Status Update: %v terminations scheduled today", len(s.entries))
+	for _, chaos := range s.entries {
+		glog.V(4).Infof("Deployment %s scheduled for termination at %s", chaos.Deployment().Name(), chaos.KillAt().Format("01/01/2017 18:42:05 Z0700 UTC"))
+	}
 }
 
 func New() (*Schedule, error) {
-	glog.V(2).Info("Generating schedule for terminations")
+	glog.V(3).Info("Status Update: Generating schedule for terminations")
 	deployments, err := deployments.EligibleDeployments()
 	if err != nil {
 		return nil, err