From bbcd79e3bdc80aaa1f479c7c3f4125872ce8a12d Mon Sep 17 00:00:00 2001
From: Yue Ko <yko@infoblox.com>
Date: Thu, 26 Jan 2017 16:41:19 -0500
Subject: [PATCH] Improve log and error messages (#29)

- Make sure all IPAM requests and responses are logged
- Improve error messages in responses to IPAM requests
---
 infoblox-ipam.go | 30 ++++++++++++++++++++----------
 ipam-driver.go   | 32 ++++++++++++++++++++++++--------
 2 files changed, 44 insertions(+), 18 deletions(-)

diff --git a/infoblox-ipam.go b/infoblox-ipam.go
index c0dc929..89262a7 100644
--- a/infoblox-ipam.go
+++ b/infoblox-ipam.go
@@ -74,19 +74,27 @@ func (ibDrv *InfobloxDriver) RequestAddress(r interface{}) (map[string]interface
 	if fixedAddr != nil {
 		if v.Address != "" {
 			if fixedAddr.IPAddress != v.Address {
-				log.Printf("Requested MAC address '%s' is already associated with a difference IP address '%s' (requested: '%s')",
+				msg := fmt.Sprintf("Requested MAC '%s' is already associated with a difference IP '%s' (requested: '%s')",
 					macAddr, fixedAddr.IPAddress, v.Address)
-
-				return nil, nil
+				log.Printf("RequestAddress: %s", msg)
+				return nil, errors.New(msg)
 			}
 		}
 	}
 
+	var err error
 	if fixedAddr == nil {
-		fixedAddr, _ = ibDrv.objMgr.AllocateIP(network.NetviewName, network.Cidr, v.Address, macAddr, "")
+		fixedAddr, err = ibDrv.objMgr.AllocateIP(network.NetviewName, network.Cidr, v.Address, macAddr, "")
+	}
+
+	var res map[string]interface{}
+	if fixedAddr == nil || err != nil {
+		res = map[string]interface{}{}
+	} else {
+		res = map[string]interface{}{"Address": fmt.Sprintf("%s/%s", fixedAddr.IPAddress, getPrefixLength(network.Cidr))}
 	}
 
-	return map[string]interface{}{"Address": fmt.Sprintf("%s/%s", fixedAddr.IPAddress, getPrefixLength(network.Cidr))}, nil
+	return res, err
 }
 
 func (ibDrv *InfobloxDriver) ReleaseAddress(r interface{}) (map[string]interface{}, error) {
@@ -108,8 +116,9 @@ func (ibDrv *InfobloxDriver) requestSpecificNetwork(netview string, pool string,
 	}
 	if network != nil {
 		if n, ok := network.Ea["Network Name"]; !ok || n != networkName {
-			log.Printf("requestSpecificNetwork: network is already used '%s'", *network)
-			return nil, nil
+			msg := fmt.Sprintf("Network (%s) already in use", network.Cidr)
+			log.Printf("requestSpecificNetwork: %s", msg)
+			return nil, errors.New(msg)
 		}
 	} else {
 		networkByName, err := ibDrv.objMgr.GetNetwork(netview, "", ibclient.EA{"Network Name": networkName})
@@ -118,8 +127,9 @@ func (ibDrv *InfobloxDriver) requestSpecificNetwork(netview string, pool string,
 		}
 		if networkByName != nil {
 			if networkByName.Cidr != pool {
-				log.Printf("requestSpecificNetwork: network name has different Cidr '%s'", networkByName.Cidr)
-				return nil, nil
+				msg := fmt.Sprintf("Network name (%s) has different CIDR (%s)", networkName, networkByName.Cidr)
+				log.Printf("requestSpecificNetwork: %s", msg)
+				return nil, errors.New(msg)
 			}
 		}
 	}
@@ -258,7 +268,7 @@ func (ibDrv *InfobloxDriver) ReleasePool(r interface{}) (map[string]interface{},
 
 		ref, _ := ibDrv.objMgr.DeleteNetwork(v.PoolID, networkFromRef.NetviewName)
 		if len(ref) > 0 {
-			log.Printf("Network %s deleted from Infoblox\n", v.PoolID)
+			log.Printf("Network %s successfully deleted from Infoblox\n", v.PoolID)
 		}
 	}
 
diff --git a/ipam-driver.go b/ipam-driver.go
index 24d9695..531f56a 100644
--- a/ipam-driver.go
+++ b/ipam-driver.go
@@ -12,6 +12,7 @@ import (
 	"net/http"
 	"os"
 	"reflect"
+	"strings"
 )
 
 func getDockerID() (dockerID string, err error) {
@@ -107,6 +108,16 @@ func setupSocket(pluginDir string, driverName string) string {
 	return socketFile
 }
 
+func urlToRequestType(url string) string {
+	parts := strings.Split(url, ".")
+	n := len(parts)
+	if n > 0 {
+		n = n - 1
+	}
+
+	return parts[n]
+}
+
 type ipamCall struct {
 	url string
 	f   func(r interface{}) (map[string]interface{}, error)
@@ -180,7 +191,8 @@ func main() {
 
 	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
 		url := r.URL.String()
-		log.Printf("Plugin: %s\n", url)
+		requestType := urlToRequestType(url)
+
 		if c, ok := handlers[url]; ok {
 
 			//var req interface{}
@@ -194,19 +206,23 @@ func main() {
 				}
 			}
 
+			log.Printf("'%s' request: '%s'\n", requestType, req)
 			res, err := c.f(req)
 			if err != nil || res == nil {
-				if err != nil {
-					log.Printf("IPAM Driver error '%s'", err)
-				} else if res == nil {
+				if res == nil {
 					log.Printf("IPAM Driver returned nil result")
+					res = make(map[string]interface{})
 				}
-				http.Error(w, fmt.Sprint(err), http.StatusInternalServerError)
-			} else {
-				if err := json.NewEncoder(w).Encode(res); err != nil {
-					log.Printf("%s: Bad Response Error: %s\n", url, err)
+				if err != nil {
+					log.Printf("IPAM Driver error '%s'", err)
+					res["Error"] = err.Error()
 				}
 			}
+			log.Printf("'%s' result: '%s'\n", requestType, res)
+
+			if err := json.NewEncoder(w).Encode(res); err != nil {
+				log.Printf("%s: Bad Response Error: %s\n", url, err)
+			}
 		}
 		fmt.Fprintf(w, "{ \"Error\": \"%s\"}", url)
 	})