table: revise table logs

4 files changed, 172 insertions, 51 deletions

diff --git a/table/destination.go b/table/destination.go
index 681e178f..1eda5f7c 100644
--- a/table/destination.go
+++ b/table/destination.go
@@ -63,6 +63,7 @@ type Destination interface {
 	getKnownPathList() []Path
 	setKnownPathList([]Path)
 	String() string
+	getPrefix() net.IP
 	addWithdraw(withdraw Path)
 	addNewPath(newPath Path)
 	constructWithdrawPath() Path
@@ -195,7 +196,13 @@ func (dd *DestinationDefault) removeOldPathsFromSource(source *PeerInfo) []Path
 
 func (dd *DestinationDefault) validatePath(path Path) {
 	if path == nil || path.GetRouteFamily() != dd.ROUTE_FAMILY {
-		log.Error("Invalid path. Expected %s path got %s.", dd.ROUTE_FAMILY, path)
+
+		log.WithFields(log.Fields{
+			"Topic":      "Table",
+			"Key":        dd.getNlri().String(),
+			"Path":       path,
+			"ExpectedRF": dd.ROUTE_FAMILY,
+		}).Error("path is nil or invalid route family")
 	}
 }
 
@@ -219,7 +226,12 @@ func (dest *DestinationDefault) Calculate(localAsn uint32) (Path, string, error)
 		// it becomes best path.
 		dest.knownPathList = append(dest.knownPathList, dest.newPathList[0])
 		dest.newPathList, _ = deleteAt(dest.newPathList, 0)
-		log.Debugf("best path : %s, reason=%s", dest.knownPathList[0], BPR_ONLY_PATH)
+		log.WithFields(log.Fields{
+			"Topic":  "Table",
+			"Key":    dest.getNlri().String(),
+			"Path":   dest.knownPathList[0],
+			"Reason": BPR_ONLY_PATH,
+		}).Debug("best path")
 
 		return dest.knownPathList[0], BPR_ONLY_PATH, nil
 	}
@@ -259,8 +271,11 @@ func (dest *DestinationDefault) Calculate(localAsn uint32) (Path, string, error)
 //"""
 func (dest *DestinationDefault) removeWithdrawls() {
 
-	log.Debugf("Removing %d withdrawals", len(dest.withdrawList))
-
+	log.WithFields(log.Fields{
+		"Topic":  "Table",
+		"Key":    dest.getNlri().String(),
+		"Length": len(dest.withdrawList),
+	}).Debug("Removing withdrawals")
 	// If we have no withdrawals, we have nothing to do.
 	if len(dest.withdrawList) == 0 {
 		return
@@ -269,7 +284,12 @@ func (dest *DestinationDefault) removeWithdrawls() {
 	// If we have some withdrawals and no know-paths, it means it is safe to
 	// delete these withdraws.
 	if len(dest.knownPathList) == 0 {
-		log.Debugf("Found %s withdrawals for path(s) that did not get installed", len(dest.withdrawList))
+		log.WithFields(log.Fields{
+			"Topic":  "Table",
+			"Key":    dest.getNlri().String(),
+			"Length": len(dest.withdrawList),
+		}).Debug("Found withdrawals for path(s) that did not get installed")
+
 		dest.withdrawList = dest.withdrawList[len(dest.withdrawList):]
 	}
 
@@ -294,15 +314,22 @@ func (dest *DestinationDefault) removeWithdrawls() {
 
 		// We do no have any match for this withdraw.
 		if !isFound {
-			log.Debugf("No matching path for withdraw found, may be path was not installed into table: %s", withdraw.String())
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   dest.getNlri().String(),
+				"Path":  withdraw,
+			}).Debug("No matching path for withdraw found, may be path was not installed into table")
 		}
 	}
 
 	// If we have partial match.
 	if len(matches) != len(dest.withdrawList) {
-		log.Debugf(
-			"Did not find match for some withdrawals. Number of matches(%d), number of withdrawals (%d)",
-			len(matches), len(dest.withdrawList))
+		log.WithFields(log.Fields{
+			"Topic":          "Table",
+			"Key":            dest.getNlri().String(),
+			"MatchLength":    len(matches),
+			"WithdrawLength": len(dest.withdrawList),
+		}).Debug("Did not find match for some withdrawals.")
 	}
 
 	// Clear matching paths and withdrawals.
@@ -310,14 +337,22 @@ func (dest *DestinationDefault) removeWithdrawls() {
 		var result bool = false
 		dest.knownPathList, result = removeWithPath(dest.knownPathList, path)
 		if !result {
-			log.Debugf("could not remove path: %s from knownPathList", path.String())
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   dest.getNlri().String(),
+				"Path":  path,
+			}).Debug("could not remove path from knownPathList")
 		}
 	}
 	for _, path := range wMatches {
 		var result bool = false
 		dest.withdrawList, result = removeWithPath(dest.withdrawList, path)
 		if !result {
-			log.Debugf("could not remove path: %s from withdrawList", path.String())
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   dest.getNlri().String(),
+				"Path":  path,
+			}).Debug("could not remove path from withdrawList")
 		}
 	}
 }
@@ -376,11 +411,18 @@ func (dest *DestinationDefault) removeOldPaths() {
 			match := false
 			knownPaths, match = removeWithPath(knownPaths, oldPath)
 			if !match {
-				log.Debugf("not exist withdrawal of old path in known paths: %s ", oldPath.String())
+				log.WithFields(log.Fields{
+					"Topic": "Table",
+					"Key":   dest.getNlri().String(),
+					"Path":  oldPath,
+				}).Debug("not matched")
 
 			}
-			log.Debugf("Implicit withdrawal of old path, "+
-				"since we have learned new path from same source: %s", oldPath.String())
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   dest.getNlri().String(),
+				"Path":  oldPath,
+			}).Debug("Implicit withdrawal of old path, since we have learned new path from the same peer")
 		}
 	}
 	dest.knownPathList = knownPaths
@@ -502,8 +544,7 @@ func compareByReachableNexthop(path1, path2 Path) Path {
 	//
 	//	If no path matches this criteria, return None.
 	//  However RouteServer doesn't need to check reachability, so return nil.
-	log.Debugf("enter compareByReachableNexthop")
-	log.Debugf("path1: %s, path2: %s", path1, path2)
+	log.Debugf("enter compareByReachableNexthop -- path1: %s, path2: %s", path1, path2)
 	return nil
 }
 
@@ -514,8 +555,7 @@ func compareByHighestWeight(path1, path2 Path) Path {
 	//	is configured.
 	//	Return:
 	//	nil if best path among given paths cannot be decided, else best path.
-	log.Debugf("enter compareByHighestWeight")
-	log.Debugf("path1: %s, path2: %s", path1, path2)
+	log.Debugf("enter compareByHighestWeight -- path1: %s, path2: %s", path1, path2)
 	return nil
 }
 
@@ -587,7 +627,12 @@ func compareByASPath(path1, path2 Path) Path {
 	asPath2 := attribute2.(*bgp.PathAttributeAsPath)
 
 	if asPath1 == nil || asPath2 == nil {
-		log.Error("it is not possible to compare asPath are not present")
+		log.WithFields(log.Fields{
+			"Topic":   "Table",
+			"Key":     "compareByASPath",
+			"ASPath1": asPath1,
+			"ASPath2": asPath2,
+		}).Error("can't compare ASPath because it's not present")
 	}
 
 	var l1, l2 int
@@ -599,7 +644,7 @@ func compareByASPath(path1, path2 Path) Path {
 		l2 += pathParam.ASLen()
 	}
 
-	log.Debugf("l1: %d, l2: %d", l1, l2)
+	log.Debugf("compareByASPath -- l1: %d, l2: %d", l1, l2)
 	log.Debug(reflect.TypeOf(asPath1.Value))
 	log.Debug(asPath1.Value)
 	if l1 > l2 {
@@ -621,14 +666,18 @@ func compareByOrigin(path1, path2 Path) Path {
 	_, attribute2 := path2.getPathAttr(bgp.BGP_ATTR_TYPE_ORIGIN)
 
 	if attribute1 == nil || attribute2 == nil {
-		log.Error("it is not possible to compare origin are not present")
+		log.WithFields(log.Fields{
+			"Topic":   "Table",
+			"Key":     "compareByOrigin",
+			"Origin1": attribute1,
+			"Origin2": attribute2,
+		}).Error("can't compare origin because it's not present")
 		return nil
 	}
 
 	origin1, n1 := binary.Uvarint(attribute1.(*bgp.PathAttributeOrigin).Value)
 	origin2, n2 := binary.Uvarint(attribute2.(*bgp.PathAttributeOrigin).Value)
-	log.Debugf("path1 origin value: %d, %d byte read", origin1, n1)
-	log.Debugf("path2 origin value: %d, %d byte read", origin2, n2)
+	log.Debugf("compareByOrigin -- origin1: %d(%d), origin2: %d(%d)", origin1, n1, origin2, n2)
 
 	// If both paths have same origins
 	if origin1 == origin2 {
@@ -661,7 +710,7 @@ func compareByMED(path1, path2 Path) Path {
 
 	med1 := getMed(path1)
 	med2 := getMed(path2)
-
+	log.Debugf("compareByMED -- med1: %d, med2: %d", med1, med2)
 	if med1 == med2 {
 		return nil
 	} else if med1 < med2 {
@@ -689,6 +738,7 @@ func compareByASNumber(localAsn uint32, path1, path2 Path) Path {
 
 	p1Asn := getPathSourceAsn(path1)
 	p2Asn := getPathSourceAsn(path2)
+	log.Debugf("compareByASNumber -- p1Asn: %d, p2Asn: %d", p1Asn, p2Asn)
 	// If path1 is from ibgp peer and path2 is from ebgp peer.
 	if (p1Asn == localAsn) && (p2Asn != localAsn) {
 		return path2
@@ -708,8 +758,7 @@ func compareByIGPCost(path1, path2 Path) Path {
 	//
 	//	Return None if igp cost is same.
 	// Currently BGPS has no concept of IGP and IGP cost.
-	log.Debugf("enter compareByIGPCost")
-	log.Debugf("path1: %s, path2: %s", path1, path2)
+	log.Debugf("enter compareByIGPCost -- path1: %v, path2: %v", path1, path2)
 	return nil
 }
 
diff --git a/table/path.go b/table/path.go
index f6ecf05c..10374aa7 100644
--- a/table/path.go
+++ b/table/path.go
@@ -58,9 +58,13 @@ type PathDefault struct {
 }
 
 func NewPathDefault(rf bgp.RouteFamily, source *PeerInfo, nlri bgp.AddrPrefixInterface, nexthop net.IP, isWithdraw bool, pattrs []bgp.PathAttributeInterface, medSetByTargetNeighbor bool, now time.Time) *PathDefault {
-
 	if !isWithdraw && pattrs == nil {
-		log.Error("Need to provide nexthop and patattrs for path that is not a withdraw.")
+		log.WithFields(log.Fields{
+			"Topic":   "Table",
+			"Key":     nlri.String(),
+			"Peer":    source.Address.String(),
+			"Nexthop": nexthop.String(),
+		}).Error("Need to provide nexthop and patattrs for the path that is not withdraw.")
 		return nil
 	}
 
@@ -103,7 +107,11 @@ func (pd *PathDefault) clone(isWithdraw bool) Path {
 	nlri := pd.nlri
 	if isWithdraw {
 		if pd.IsWithdraw() {
-			log.Fatal("Withdraw path is not supposed to be cloned")
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   pd.getNlri().String(),
+				"Peer":  pd.getSource().Address.String(),
+			}).Fatal("Withdraw path is not supposed to be cloned")
 		} else {
 			nlri = &bgp.WithdrawnRoute{pd.nlri.(*bgp.NLRInfo).IPAddrPrefix}
 		}
@@ -206,15 +214,15 @@ func (pi *PathDefault) getPrefix() string {
 func CreatePath(source *PeerInfo, nlri bgp.AddrPrefixInterface, attrs []bgp.PathAttributeInterface, isWithdraw bool, now time.Time) Path {
 
 	rf := bgp.RouteFamily(int(nlri.AFI())<<16 | int(nlri.SAFI()))
-	log.Debugf("afi: %d, safi: %d ", int(nlri.AFI()), nlri.SAFI())
+	log.Debugf("CreatePath afi: %d, safi: %d ", int(nlri.AFI()), nlri.SAFI())
 	var path Path
 
 	switch rf {
 	case bgp.RF_IPv4_UC:
-		log.Debugf("RouteFamily : %s", bgp.RF_IPv4_UC.String())
+		log.Debugf("CreatePath RouteFamily : %s", bgp.RF_IPv4_UC.String())
 		path = NewIPv4Path(source, nlri, isWithdraw, attrs, false, now)
 	case bgp.RF_IPv6_UC:
-		log.Debugf("RouteFamily : %s", bgp.RF_IPv6_UC.String())
+		log.Debugf("CreatePath RouteFamily : %s", bgp.RF_IPv6_UC.String())
 		path = NewIPv6Path(source, nlri, isWithdraw, attrs, false, now)
 	}
 	return path
@@ -262,7 +270,11 @@ func (ipv6p *IPv6Path) clone(isWithdraw bool) Path {
 	nlri := ipv6p.nlri
 	if isWithdraw {
 		if ipv6p.IsWithdraw() {
-			log.Fatal("Withdraw path is not supposed to be cloned")
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   ipv6p.getNlri().String(),
+				"Peer":  ipv6p.getSource().Address.String(),
+			}).Fatal("Withdraw path is not supposed to be cloned")
 		}
 	}
 	return CreatePath(ipv6p.source, nlri, ipv6p.pathAttrs, isWithdraw, ipv6p.PathDefault.timestamp)
diff --git a/table/table.go b/table/table.go
index 79b310d2..2bc328d8 100644
--- a/table/table.go
+++ b/table/table.go
@@ -163,7 +163,19 @@ func deleteDest(table Table, dest Destination) {
 
 func (td *TableDefault) validatePath(path Path) {
 	if path == nil || path.GetRouteFamily() != td.ROUTE_FAMILY {
-		log.Errorf("Invalid path. Expected instance of %s route family path, got %s.", td.ROUTE_FAMILY, path)
+		if path == nil {
+			log.WithFields(log.Fields{
+				"Topic": "Table",
+				"Key":   td.ROUTE_FAMILY,
+			}).Error("path is nil")
+		} else if path.GetRouteFamily() != td.ROUTE_FAMILY {
+			log.WithFields(log.Fields{
+				"Topic":      "Table",
+				"Key":        td.ROUTE_FAMILY,
+				"Prefix":     path.getNlri().String(),
+				"ReceivedRf": path.GetRouteFamily().String(),
+			}).Error("Invalid path. RouteFamily mismatch")
+		}
 	}
 	_, attr := path.getPathAttr(bgp.BGP_ATTR_TYPE_AS_PATH)
 	if attr != nil {
@@ -171,30 +183,42 @@ func (td *TableDefault) validatePath(path Path) {
 		for _, as := range pathParam {
 			_, y := as.(*bgp.As4PathParam)
 			if !y {
-				log.Fatal("AsPathParam must be converted to As4PathParam, ", as)
+				log.WithFields(log.Fields{
+					"Topic": "Table",
+					"Key":   td.ROUTE_FAMILY,
+					"As":    as,
+				}).Fatal("AsPathParam must be converted to As4PathParam")
 			}
 		}
 	}
 
 	_, attr = path.getPathAttr(bgp.BGP_ATTR_TYPE_AS4_PATH)
 	if attr != nil {
-		log.Fatal("AS4_PATH must be converted to AS_PATH")
+		log.WithFields(log.Fields{
+			"Topic": "Table",
+			"Key":   td.ROUTE_FAMILY,
+		}).Fatal("AS4_PATH must be converted to AS_PATH")
 	}
 }
 
 func (td *TableDefault) validateNlri(nlri bgp.AddrPrefixInterface) {
 	if nlri == nil {
-		log.Error("Invalid Vpnv4 prefix given.")
+		log.WithFields(log.Fields{
+			"Topic": "Table",
+			"Key":   td.ROUTE_FAMILY,
+			"Nlri":  nlri,
+		}).Error("Invalid Vpnv4 prefix given.")
+
 	}
 }
 
 func getOrCreateDest(table Table, nlri bgp.AddrPrefixInterface) Destination {
-	log.Debugf("Table type : %s", reflect.TypeOf(table))
+	log.Debugf("getOrCreateDest Table type : %s", reflect.TypeOf(table))
 	tableKey := table.tableKey(nlri)
 	dest := table.getDestination(tableKey)
 	// If destination for given prefix does not exist we create it.
 	if dest == nil {
-		log.Debugf("dest with key %s is not found", tableKey)
+		log.Debugf("getOrCreateDest dest with key %s is not found", tableKey)
 		dest = table.createDest(nlri)
 		table.setDestination(tableKey, dest)
 	}
diff --git a/table/table_manager.go b/table/table_manager.go
index a6fda7e3..d6dde9d0 100644
--- a/table/table_manager.go
+++ b/table/table_manager.go
@@ -140,10 +140,21 @@ func (manager *TableManager) calculate(destinationList []Destination) ([]Path, [
 
 	for _, destination := range destinationList {
 		// compute best path
-		log.Infof("Processing destination: %v", destination.String())
+
+		log.WithFields(log.Fields{
+			"Topic": "table",
+			"Key":   destination.getPrefix().String(),
+		}).Info("Processing destination")
+
 		newBestPath, reason, err := destination.Calculate(manager.localAsn)
 
-		log.Debugf("new best path: %v, reason=%v", newBestPath, reason)
+		log.WithFields(log.Fields{
+			"Topic":  "table",
+			"Key":    destination.getPrefix().String(),
+			"new":    newBestPath,
+			"reason": reason,
+		}).Debug("new best path")
+
 		if err != nil {
 			log.Error(err)
 			continue
@@ -154,29 +165,46 @@ func (manager *TableManager) calculate(destinationList []Destination) ([]Path, [
 
 		if newBestPath != nil && currentBestPath == newBestPath {
 			// best path is not changed
-			log.Debug("best path is not changed")
+			log.WithFields(log.Fields{
+				"Topic": "table",
+				"Key":   destination.getPrefix().String(),
+			}).Debug("best path is not changed")
 			continue
 		}
 
 		if newBestPath == nil {
-			log.Debug("best path is nil")
+			log.WithFields(log.Fields{
+				"Topic": "table",
+				"Key":   destination.getPrefix().String(),
+			}).Debug("best path is nil")
+
 			if len(destination.getKnownPathList()) == 0 {
 				// create withdraw path
 				if currentBestPath != nil {
-					log.Debug("best path is lost")
+					log.WithFields(log.Fields{
+						"Topic": "table",
+						"Key":   destination.getPrefix().String(),
+					}).Debug("best path is lost")
+
 					p := destination.getBestPath()
 					destination.setOldBestPath(p)
 					lostPaths = append(lostPaths, p.clone(true))
 				}
 				destination.setBestPath(nil)
 			} else {
-				log.Error("known path list is not empty")
+
+				log.WithFields(log.Fields{
+					"Topic": "table",
+					"Key":   destination.getPrefix().String(),
+				}).Error("known path list is not empty")
 			}
 		} else {
-			log.Debugf("new best path: NLRI: %v, next_hop=%v, reason=%v",
-				newBestPath.getPrefix(),
-				newBestPath.getNexthop(),
-				reason)
+			log.WithFields(log.Fields{
+				"Topic":    "table",
+				"Key":      newBestPath.getPrefix(),
+				"next_hop": newBestPath.getNexthop(),
+				"reason":   reason,
+			}).Debug("new best path")
 
 			bestPaths = append(bestPaths, newBestPath)
 			destination.setBestPath(newBestPath)
@@ -186,7 +214,11 @@ func (manager *TableManager) calculate(destinationList []Destination) ([]Path, [
 			rf := destination.getRouteFamily()
 			t := manager.Tables[rf]
 			deleteDest(t, destination)
-			log.Debugf("destination removed route_family=%v, destination=%v", rf, destination)
+			log.WithFields(log.Fields{
+				"Topic":        "table",
+				"Key":          destination.getPrefix().String(),
+				"route_family": rf,
+			}).Debug("destination removed")
 		}
 	}
 	return bestPaths, lostPaths, nil
@@ -214,7 +246,11 @@ func (manager *TableManager) ProcessPaths(pathList []Path) ([]Path, []Path, erro
 func (manager *TableManager) ProcessUpdate(fromPeer *PeerInfo, message *bgp.BGPMessage) ([]Path, []Path, error) {
 	// check msg's type if it's BGPUpdate
 	if message.Header.Type != bgp.BGP_MSG_UPDATE {
-		log.Warn("message is not BGPUpdate")
+		log.WithFields(log.Fields{
+			"Topic": "table",
+			"key":   fromPeer.Address.String(),
+			"type":  message.Header.Type,
+		}).Warn("message is not BGPUpdate")
 		return []Path{}, []Path{}, nil
 	}