all logging is done with log.WithFields

Signed-off-by: dsp <dsp@2f30.org>
Signed-off-by: ISHIDA Wataru <ishida.wataru@lab.ntt.co.jp>

6 files changed, 97 insertions, 42 deletions

diff --git a/server/bmp.go b/server/bmp.go
index 084066ab..3522da98 100644
--- a/server/bmp.go
+++ b/server/bmp.go
@@ -30,7 +30,7 @@ import (
 func (b *bmpClient) tryConnect() *net.TCPConn {
 	interval := 1
 	for {
-		log.Debug("connecting bmp server: ", b.host)
+		log.WithFields(log.Fields{"Topic": "bmp"}).Debugf("Connecting BMP server:%s", b.host)
 		conn, err := net.Dial("tcp", b.host)
 		if err != nil {
 			select {
@@ -43,7 +43,7 @@ func (b *bmpClient) tryConnect() *net.TCPConn {
 				interval *= 2
 			}
 		} else {
-			log.Info("bmp server is connected, ", b.host)
+			log.WithFields(log.Fields{"Topic": "bmp"}).Infof("BMP server is connected:%s", b.host)
 			return conn.(*net.TCPConn)
 		}
 	}
diff --git a/server/collector.go b/server/collector.go
index 583a1999..59f945be 100644
--- a/server/collector.go
+++ b/server/collector.go
@@ -111,11 +111,11 @@ func path2data(path *table.Path) (map[string]interface{}, map[string]string) {
 	}
 
 	if err := bgp.FlatUpdate(tags, path.GetNlri().Flat()); err != nil {
-		log.Error(err)
+		log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("NLRI FlatUpdate failed")
 	}
 	for _, p := range path.GetPathAttrs() {
 		if err := bgp.FlatUpdate(tags, p.Flat()); err != nil {
-			log.Error(err)
+			log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("PathAttr FlatUpdate failed")
 		}
 	}
 	return fields, tags
@@ -173,15 +173,15 @@ func (c *Collector) loop() {
 			switch msg := ev.(type) {
 			case *WatchEventUpdate:
 				if err := c.writeUpdate(msg); err != nil {
-					log.Error(err)
+					log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("Failed to write update event message")
 				}
 			case *WatchEventPeerState:
 				if err := c.writePeer(msg); err != nil {
-					log.Error(err)
+					log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("Failed to write state changed event message")
 				}
 			case *WatchEventAdjIn:
 				if err := c.writeTable(msg); err != nil {
-					log.Error(err)
+					log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("Failed to write Adj-In event message")
 				}
 			}
 		}
@@ -199,12 +199,13 @@ func NewCollector(s *BgpServer, url, dbName string, interval uint64) (*Collector
 	_, _, err = c.Ping(0)
 	if err != nil {
 		log.Error("can not connect to InfluxDB")
+		log.WithFields(log.Fields{"Type": "collector", "Error": err}).Error("Failed to connect to InfluxDB")
 		return nil, err
 	}
 
 	q := client.NewQuery("CREATE DATABASE "+dbName, "", "")
 	if response, err := c.Query(q); err != nil || response.Error() != nil {
-		log.Error("can not create database " + dbName)
+		log.WithFields(log.Fields{"Type": "collector", "Error": err}).Errorf("Failed to create database:%s", dbName)
 		return nil, err
 	}
 
diff --git a/server/fsm.go b/server/fsm.go
index babfde5e..780a2b32 100644
--- a/server/fsm.go
+++ b/server/fsm.go
@@ -436,7 +436,7 @@ func (h *FSMHandler) idle() (bgp.FSMState, FsmStateReason) {
 				return bgp.BGP_FSM_ACTIVE, FSM_IDLE_HOLD_TIMER_EXPIRED
 
 			} else {
-				log.Debug("IdleHoldTimer expired, but stay at idle because the admin state is DOWN")
+				log.WithFields(log.Fields{"Topic": "Peer"}).Debug("IdleHoldTimer expired, but stay at idle because the admin state is DOWN")
 			}
 
 		case s := <-fsm.adminStateCh:
@@ -1263,7 +1263,7 @@ func (h *FSMHandler) loop() error {
 	}
 
 	e := time.AfterFunc(time.Second*120, func() {
-		log.Fatal("failed to free the fsm.h.t for ", fsm.pConf.Config.NeighborAddress, oldState, nextState)
+		log.WithFields(log.Fields{"Topic": "Peer"}).Fatalf("failed to free the fsm.h.t for %s %s %s", fsm.pConf.Config.NeighborAddress, oldState, nextState)
 	})
 	h.t.Wait()
 	e.Stop()
diff --git a/server/mrt.go b/server/mrt.go
index dcbd3542..9241eabd 100644
--- a/server/mrt.go
+++ b/server/mrt.go
@@ -69,7 +69,8 @@ func (m *mrtWriter) loop() error {
 				log.WithFields(log.Fields{
 					"Topic": "mrt",
 					"Data":  m,
-				}).Warn(err)
+					"Error": err,
+				}).Warn("Failed to create MRT message in serialize()")
 				return nil, err
 			}
 			return bm.Serialize()
@@ -92,7 +93,7 @@ func (m *mrtWriter) loop() error {
 					log.WithFields(log.Fields{
 						"Topic": "mrt",
 						"Error": err,
-					}).Warn(err)
+					}).Warn("Can't write to destination MRT file")
 				}
 			}
 
@@ -103,7 +104,8 @@ func (m *mrtWriter) loop() error {
 					log.WithFields(log.Fields{
 						"Topic": "mrt",
 						"Data":  e,
-					}).Warn(err)
+						"Error": err,
+					}).Warn("Failed to serialize event")
 					continue
 				}
 				b.Write(buf)
@@ -128,7 +130,10 @@ func (m *mrtWriter) loop() error {
 			if err == nil {
 				m.file = file
 			} else {
-				log.Info("can't rotate mrt file", err)
+				log.WithFields(log.Fields{
+					"Topic": "mrt",
+					"Error": err,
+				}).Warn("can't rotate MRT file")
 			}
 		}
 	}
@@ -139,6 +144,11 @@ func mrtFileOpen(filename string, interval uint64) (*os.File, error) {
 	if interval != 0 {
 		realname = time.Now().Format(filename)
 	}
+	log.WithFields(log.Fields{
+		"Topic":         "mrt",
+		"Filename":      realname,
+		"Dump Interval": interval,
+	}).Debug("Setting new MRT destination file")
 
 	i := len(realname)
 	for i > 0 && os.IsPathSeparator(realname[i-1]) {
@@ -153,14 +163,20 @@ func mrtFileOpen(filename string, interval uint64) (*os.File, error) {
 
 	if j > 0 {
 		if err := os.MkdirAll(realname[0:j-1], 0755); err != nil {
-			log.Warn(err)
+			log.WithFields(log.Fields{
+				"Topic": "mrt",
+				"Error": err,
+			}).Warn("can't create MRT destination directory")
 			return nil, err
 		}
 	}
 
 	file, err := os.OpenFile(realname, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0644)
 	if err != nil {
-		log.Warn(err)
+		log.WithFields(log.Fields{
+			"Topic": "mrt",
+			"Error": err,
+		}).Warn("can't create MRT destination file")
 	}
 	return file, err
 }
diff --git a/server/rpki.go b/server/rpki.go
index c91ee7c0..df105a65 100644
--- a/server/rpki.go
+++ b/server/rpki.go
@@ -158,7 +158,7 @@ func (m *roaManager) AddServer(host string, lifetime int64) error {
 		lifetime = 3600
 	}
 	if _, ok := m.clientMap[host]; ok {
-		return fmt.Errorf("roa server exists %s", host)
+		return fmt.Errorf("ROA server exists %s", host)
 	}
 	client := NewRoaClient(address, port, m.eventCh, lifetime)
 	m.clientMap[host] = client
@@ -169,7 +169,7 @@ func (m *roaManager) AddServer(host string, lifetime int64) error {
 func (m *roaManager) DeleteServer(host string) error {
 	client, ok := m.clientMap[host]
 	if !ok {
-		return fmt.Errorf("roa server doesn't exists %s", host)
+		return fmt.Errorf("ROA server doesn't exists %s", host)
 	}
 	client.reset()
 	delete(m.clientMap, host)
@@ -208,7 +208,7 @@ func (m *roaManager) Enable(address string) error {
 			return nil
 		}
 	}
-	return fmt.Errorf("roa server not found %s", address)
+	return fmt.Errorf("ROA server not found %s", address)
 }
 
 func (m *roaManager) Disable(address string) error {
@@ -219,7 +219,7 @@ func (m *roaManager) Disable(address string) error {
 			return nil
 		}
 	}
-	return fmt.Errorf("roa server not found %s", address)
+	return fmt.Errorf("ROA server not found %s", address)
 }
 
 func (m *roaManager) Reset(address string) error {
@@ -230,7 +230,7 @@ func (m *roaManager) Reset(address string) error {
 			return nil
 		}
 	}
-	return fmt.Errorf("roa server not found %s", address)
+	return fmt.Errorf("ROA server not found %s", address)
 }
 
 func (m *roaManager) SoftReset(address string) error {
@@ -242,7 +242,7 @@ func (m *roaManager) SoftReset(address string) error {
 			return nil
 		}
 	}
-	return fmt.Errorf("roa server not found %s", address)
+	return fmt.Errorf("ROA server not found %s", address)
 }
 
 func (c *roaManager) ReceiveROA() chan *ROAEvent {
@@ -262,12 +262,12 @@ func (m *roaManager) HandleROAEvent(ev *ROAEvent) {
 		if ev.EventType == CONNECTED {
 			ev.conn.Close()
 		}
-		log.Error("can't find %s roa server configuration", ev.Src)
+		log.WithFields(log.Fields{"Topic": "rpki"}).Errorf("Can't find %s ROA server configuration", ev.Src)
 		return
 	}
 	switch ev.EventType {
 	case DISCONNECTED:
-		log.Info("roa server is disconnected, ", ev.Src)
+		log.WithFields(log.Fields{"Topic": "rpki"}).Infof("ROA server %s is disconnected", ev.Src)
 		client.state.Downtime = time.Now().Unix()
 		// clear state
 		client.endOfData = false
@@ -279,7 +279,7 @@ func (m *roaManager) HandleROAEvent(ev *ROAEvent) {
 		client.timer = time.AfterFunc(time.Duration(client.lifetime)*time.Second, client.lifetimeout)
 		client.oldSessionID = client.sessionID
 	case CONNECTED:
-		log.Info("roa server is connected, ", ev.Src)
+		log.WithFields(log.Fields{"Topic": "rpki"}).Infof("ROA server %s is connected", ev.Src)
 		client.conn = ev.conn
 		client.state.Uptime = time.Now().Unix()
 		client.t = tomb.Tomb{}
@@ -295,9 +295,9 @@ func (m *roaManager) HandleROAEvent(ev *ROAEvent) {
 		// all stale ROAs were deleted -> timer was cancelled
 		// so should not be here.
 		if client.oldSessionID != client.sessionID {
-			log.Info("reconnected so ignore timeout", client.host)
+			log.WithFields(log.Fields{"Topic": "rpki"}).Infof("Reconnected to %s. Ignore timeout", client.host)
 		} else {
-			log.Info("delete all due to timeout", client.host)
+			log.WithFields(log.Fields{"Topic": "rpki"}).Infof("Deleting all ROAs due to timeout with:%s", client.host)
 			m.deleteAllROA(client.host)
 		}
 	}
@@ -330,7 +330,13 @@ func (m *roaManager) deleteROA(roa *ROA) {
 			return
 		}
 	}
-	log.Info("can't withdraw a roa", roa.Prefix.Prefix.String(), roa.Prefix.Length, roa.AS, roa.MaxLen)
+	log.WithFields(log.Fields{
+		"Topic":         "rpki",
+		"Prefix":        roa.Prefix.Prefix.String(),
+		"Prefix Length": roa.Prefix.Length,
+		"AS":            roa.AS,
+		"Max Length":    roa.MaxLen,
+	}).Info("Can't withdraw a ROA")
 }
 
 func (m *roaManager) addROA(roa *ROA) {
@@ -419,7 +425,11 @@ func (c *roaManager) handleRTRMsg(client *roaClient, state *config.RpkiServerSta
 			received.Error++
 		}
 	} else {
-		log.Info("failed to parse a RTR message ", client.host, err)
+		log.WithFields(log.Fields{
+			"Topic": "rpki",
+			"Host":  client.host,
+			"Error": err,
+		}).Info("Failed to parse an RTR message")
 	}
 }
 
diff --git a/server/server.go b/server/server.go
index cfbe514f..889e677e 100644
--- a/server/server.go
+++ b/server/server.go
@@ -76,7 +76,10 @@ func NewTCPListener(address string, port uint32, ch chan *net.TCPConn) (*TCPList
 			conn, err := l.AcceptTCP()
 			if err != nil {
 				close(closeCh)
-				log.Warn(err)
+				log.WithFields(log.Fields{
+					"Topic": "Peer",
+					"Error": err,
+				}).Warn("Failed to AcceptTCP")
 				return err
 			}
 			ch <- conn
@@ -148,11 +151,15 @@ func (server *BgpServer) Serve() {
 	handleFsmMsg := func(e *FsmMsg) {
 		peer, found := server.neighborMap[e.MsgSrc]
 		if !found {
-			log.Warn("Can't find the neighbor ", e.MsgSrc)
+			log.WithFields(log.Fields{
+				"Topic": "Peer",
+			}).Warnf("Cant't find the neighbor %s", e.MsgSrc)
 			return
 		}
 		if e.Version != peer.fsm.version {
-			log.Debug("FSM Version inconsistent")
+			log.WithFields(log.Fields{
+				"Topic": "Peer",
+			}).Debug("FSM version inconsistent")
 			return
 		}
 		server.handleFSMMessage(peer, e)
@@ -166,7 +173,11 @@ func (server *BgpServer) Serve() {
 			peer, found := server.neighborMap[remoteAddr]
 			if found {
 				if peer.fsm.adminState != ADMIN_STATE_UP {
-					log.Debug("new connection for non admin-state-up peer ", remoteAddr, peer.fsm.adminState)
+					log.WithFields(log.Fields{
+						"Topic":       "Peer",
+						"Remote Addr": remoteAddr,
+						"Admin State": peer.fsm.adminState,
+					}).Debug("New connection for non admin-state-up peer")
 					conn.Close()
 					return
 				}
@@ -196,10 +207,14 @@ func (server *BgpServer) Serve() {
 					conn.Close()
 					return
 				}
-				log.Debug("accepted a new passive connection from ", remoteAddr)
+				log.WithFields(log.Fields{
+					"Topic": "Peer",
+				}).Debugf("Accepted a new passive connection from:%s", remoteAddr)
 				peer.PassConn(conn)
 			} else {
-				log.Info("can't find configuration for a new passive connection from ", remoteAddr)
+				log.WithFields(log.Fields{
+					"Topic": "Peer",
+				}).Infof("Can't find configuration for a new passive connection from:%s", remoteAddr)
 				conn.Close()
 			}
 		}
@@ -641,7 +656,7 @@ func (server *BgpServer) handleFSMMessage(peer *Peer, e *FsmMsg) {
 				log.WithFields(log.Fields{
 					"Topic": "Peer",
 					"Key":   peer.ID(),
-				}).Debugf("now syncing, suppress sending updates. start deferral timer(%d)", deferral)
+				}).Debugf("Now syncing, suppress sending updates. start deferral timer(%d)", deferral)
 				time.AfterFunc(time.Second*time.Duration(deferral), deferralExpiredFunc(bgp.RouteFamily(0)))
 			}
 		} else {
@@ -1567,10 +1582,14 @@ func (s *BgpServer) GetAdjRib(addr string, family bgp.RouteFamily, in bool, pref
 		var paths []*table.Path
 		if in {
 			paths = peer.adjRibIn.PathList([]bgp.RouteFamily{family}, false)
-			log.Debugf("RouteFamily=%v adj-rib-in found : %d", family.String(), len(paths))
+			log.WithFields(log.Fields{
+				"Topic": "Peer",
+			}).Debugf("RouteFamily=%v adj-rib-in found : %d", family.String(), len(paths))
 		} else {
 			paths = peer.adjRibOut.PathList([]bgp.RouteFamily{family}, false)
-			log.Debugf("RouteFamily=%v adj-rib-out found : %d", family.String(), len(paths))
+			log.WithFields(log.Fields{
+				"Topic": "Peer",
+			}).Debugf("RouteFamily=%v adj-rib-out found : %d", family.String(), len(paths))
 		}
 
 		for i, p := range paths {
@@ -1664,7 +1683,9 @@ func (server *BgpServer) addNeighbor(c *config.Neighbor) error {
 			SetTcpMD5SigSockopts(l, addr, c.Config.AuthPassword)
 		}
 	}
-	log.Info("Add a peer configuration for ", addr)
+	log.WithFields(log.Fields{
+		"Topic": "Peer",
+	}).Infof("Add a peer configuration for:%s", addr)
 
 	peer := NewPeer(&server.bgpConfig.Global, c, server.globalRib, server.policy)
 	server.setPolicyByConfig(peer.ID(), c.ApplyPolicy)
@@ -1716,16 +1737,23 @@ func (server *BgpServer) deleteNeighbor(c *config.Neighbor, code, subcode uint8)
 	for _, l := range server.Listeners(addr) {
 		SetTcpMD5SigSockopts(l, addr, "")
 	}
-	log.Info("Delete a peer configuration for ", addr)
+	log.WithFields(log.Fields{
+		"Topic": "Peer",
+	}).Infof("Delete a peer configuration for:%s", addr)
 
 	n.fsm.sendNotification(code, subcode, nil, "")
 
 	go func(addr string) {
-		t := time.AfterFunc(time.Minute*5, func() { log.Fatal("failed to free the fsm.h.t for ", addr) })
+		logfatal := func() {
+			log.WithFields(log.Fields{
+				"Topic": "Peer",
+			}).Fatalf("Failed to free the fsm.h.t for %s", addr)
+		}
+		t := time.AfterFunc(time.Minute*5, logfatal)
 		n.fsm.h.t.Kill(nil)
 		n.fsm.h.t.Wait()
 		t.Stop()
-		t = time.AfterFunc(time.Minute*5, func() { log.Fatal("failed to free the fsm.h for ", addr) })
+		t = time.AfterFunc(time.Minute*5, logfatal)
 		n.fsm.t.Kill(nil)
 		n.fsm.t.Wait()
 		t.Stop()