updated to better handle all responses from the provisioner as well as add more debugging information

Change-Id: I217df62b42c339b387f65bc6c6bf7a1bc56fa3ed
diff --git a/automation/state.go b/automation/state.go
index 30d3f06..5890b31 100644
--- a/automation/state.go
+++ b/automation/state.go
@@ -169,12 +169,12 @@
 	}
 
 	record, err := options.ProvTracker.Get(node.ID())
-	if options.Verbose {
-		log.Printf("[info] Current state of node '%s' is '%s'", node.Hostname(), record.State.String())
-	}
 	if err != nil {
 		log.Printf("[warn] unable to retrieve provisioning state of node '%s' : %s", node.Hostname(), err)
 	} else if record.State == Unprovisioned || record.State == ProvisionError {
+		if options.Verbose {
+			log.Printf("[info] Current state of node '%s' is '%s'", node.Hostname(), record.State.String())
+		}
 		var err error = nil
 		var callout *url.URL
 		log.Printf("PROVISION '%s'", node.Hostname())
@@ -298,6 +298,9 @@
 						node.Hostname(), err)
 				} else {
 					defer resp.Body.Close()
+					if options.Verbose {
+						log.Printf("[debug] Got status '%s' for node '%s'", resp.Status, node.Hostname())
+					}
 					switch resp.StatusCode {
 					case http.StatusOK: // provisioning completed or failed
 						decoder := json.NewDecoder(resp.Body)
@@ -331,6 +334,8 @@
 						}
 					case http.StatusAccepted: // in the provisioning state
 						// Noop, presumably alread in this state
+					case http.StatusNotFound:
+						// Noop, but not an error
 					default: // Consider anything else an erorr
 						log.Printf("[warn] Node '%s' with ID '%s' failed provisioning, will retry",
 							node.Hostname(), node.ID())
diff --git a/provisioner/handlers.go b/provisioner/handlers.go
index c2e78ba..6a7bb01 100644
--- a/provisioner/handlers.go
+++ b/provisioner/handlers.go
@@ -59,22 +59,26 @@
 	decoder := json.NewDecoder(r.Body)
 	defer r.Body.Close()
 	if err := decoder.Decode(&info); err != nil {
+		log.Printf("[error] Unable to decode request to provision : %s", err)
 		http.Error(w, err.Error(), http.StatusBadRequest)
 		return
 	}
 
 	if !c.validateData(&info) {
+		log.Printf("[errpr] Provisioning request not valid for '%s'", info.Name)
 		w.WriteHeader(http.StatusBadRequest)
 		return
 	}
 
 	role, err := c.GetRole(&info)
 	if err != nil {
+		log.Printf("[error] unable to get provisioning role for node '%s' : %s", info.Name, err)
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
 	}
 	err = c.dispatcher.Dispatch(&info, role, c.config.Script)
 	if err != nil {
+		log.Printf("[errpr] unable to dispatch provisioning request for node '%s' : %s", info.Name, err)
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
 	}