added logging to core functionality

cli/path_traversal.go

@@ -6,7 +6,6 @@ import (
 )
 
 func PathTraversal() error {
-	log.SetLevel(log.DebugLevel)
 	paths, err := path.ParseSchema(testSchema, "device")
 	if err != nil {
 		return err

cli/subscribe.go

@@ -15,7 +15,6 @@ import (
 // Subscribe starts a gNMI subscriber requersting the specified paths on the target and
 // logs the response to stdout. Only 'stream' mode with 'sample' operation supported.
 func Subscribe(a, u, p string, sample, heartbeat int64, args...string) error{
-	log.SetLevel(log.DebugLevel)
 	sbi := &nucleus.OpenConfig{}
 	tOpts := &nucleus.GnmiTransportOptions{
 		Config: gnmi.Config{

cmd/root.go

@@ -45,6 +45,7 @@ var cfgFile string
 var username string
 var password string
 var address string
+var loglevel string
 
 
 // rootCmd represents the base command when called without any subcommands
@@ -78,6 +79,7 @@ func init() {
   rootCmd.PersistentFlags().StringVarP(&username, "username", "u", "admin", "username for a gnmi resource")
   rootCmd.PersistentFlags().StringVarP(&password, "password", "p", "arista", "password for a gnmi resource")
   rootCmd.PersistentFlags().StringVarP(&username, "address", "a", "ceos-cocsn.apps.ocp.fbi.h-da.de:6030", "address to a gnmi resource")
+  rootCmd.PersistentFlags().StringVarP(&loglevel, "log-level", "l", "", "log level 'debug' or 'trace'")
 }
 
 
@@ -97,8 +99,18 @@ func initConfig() {
   if err := viper.ReadInConfig(); err == nil {
     fmt.Println("Using config file:", viper.ConfigFileUsed())
   }
-  if viper.IsSet("GOSDN_DEBUG") {
+
+  loglevel = viper.GetString("GOSDN_DEBUG")
+  log.SetReportCaller(true)
+  switch loglevel {
+  case "trace":
+    log.SetLevel(log.TraceLevel)
+  case "debug":
     log.SetLevel(log.DebugLevel)
+  default:
+    log.SetLevel(log.InfoLevel)
+    log.SetFormatter(&log.JSONFormatter{})
+    log.SetReportCaller(false)
   }
 }
 

nucleus/gnmi_transport.go

@@ -24,6 +24,11 @@ func NewGnmiTransport(opts *GnmiTransportOptions) (*Gnmi, error) {
 	if err != nil {
 		return nil, err
 	}
+	log.WithFields(log.Fields{
+		"target": opts.Addr,
+		"tls": opts.TLS,
+		"encoding": opts.Encoding,
+	}).Info("building new gNMI transport")
 	return &Gnmi{
 		SetNode:  opts.SetNode,
 		RespChan: opts.RespChan,
@@ -140,6 +145,9 @@ func extraxtPathElements(path *gpb.Path) []string {
 
 // Capabilities calls GNMI capabilities
 func (g *Gnmi) Capabilities(ctx context.Context) (interface{}, error) {
+	log.WithFields(log.Fields{
+		"target": g.Options.Addr,
+	}).Info("sending gNMI capabilities request")
 	ctx = gnmi.NewContext(ctx, &g.Options.Config)
 	ctx = context.WithValue(ctx, "config", &g.Options.Config)
 	resp, err := g.client.Capabilities(ctx, &gpb.CapabilityRequest{})
@@ -163,6 +171,11 @@ func (g *Gnmi) get(ctx context.Context, paths [][]string, origin string) (interf
 // getWithRequest takes a fully formed GetRequest, performs the Get,
 // and returns any response.
 func (g *Gnmi) getWithRequest(ctx context.Context, req *gpb.GetRequest) (interface{}, error) {
+	log.WithFields(log.Fields{
+		"target": g.Options.Addr,
+		"path":   req.Path,
+	}).Info("sending gNMI get request")
+
 	resp, err := g.client.Get(ctx, req)
 	if err != nil {
 		return nil, err
@@ -174,6 +187,19 @@ func (g *Gnmi) getWithRequest(ctx context.Context, req *gpb.GetRequest) (interfa
 func (g *Gnmi) set(ctx context.Context, setOps []*gnmi.Operation,
 	exts ...*gnmi_ext.Extension) (*gpb.SetResponse, error) {
 	ctx = gnmi.NewContext(ctx, &g.Options.Config)
+	targets := make([]string, len(setOps))
+	paths := make([][]string, len(setOps))
+	values := make([]string, len(setOps))
+	for i,v := range setOps {
+		targets[i] = v.Target
+		paths[i] = v.Path
+		values[i] = v.Val
+	}
+	log.WithFields(log.Fields{
+		"targets": targets,
+		"paths": paths,
+		"values": values,
+	}).Info("sending gNMI set request")
 	return gnmi.Set(ctx, g.client, setOps, exts...)
 }
 
@@ -182,6 +208,12 @@ func (g *Gnmi) subscribe(ctx context.Context) error {
 	ctx = gnmi.NewContext(ctx, &g.Options.Config)
 	opts := ctx.Value("opts").(*gnmi.SubscribeOptions)
 	go func() {
+		log.WithFields(log.Fields{
+			"address": opts.Target,
+			"paths": opts.Paths,
+			"mode": opts.Mode,
+			"interval": opts.SampleInterval,
+		}).Info("subscribed to gNMI target")
 		for {
 			resp := <-g.RespChan
 			if resp != nil {

nucleus/principalNetworkDomain.go

@@ -2,6 +2,7 @@ package nucleus
 
 import (
 	"context"
+	log "github.com/sirupsen/logrus"
 
 	"encoding/json"
 	"github.com/google/uuid"
@@ -149,11 +150,14 @@ func (pnd *pndImplementation) MarshalDevice(uuid uuid.UUID) (string, error) {
 	if err != nil {
 		return "", err
 	}
-
+	log.WithFields(log.Fields{
+		"pnd": pnd.id,
+		"device": uuid,
+	}).Info("marshalled device")
 	return string(jsonTree), nil
 }
 
-//Request sends a request for a specific device
+//Request sends a get request to a specific device
 func (pnd *pndImplementation) Request(uuid uuid.UUID, path string) error {
 	d, err := pnd.getDevice(uuid)
 	if err != nil {
@@ -178,5 +182,9 @@ func (pnd *pndImplementation) RequestAll(path string) error {
 			return err
 		}
 	}
+	log.WithFields(log.Fields{
+		"pnd": pnd.id,
+		"path": path,
+	}).Info("sent request to all devices")
 	return nil
 }

nucleus/southbound.go

@@ -33,9 +33,6 @@ type Tapi struct {
 // The struct holds the YANG schema and a function that
 // returns an SBI specific SetNode function.
 type OpenConfig struct {
-	// deprecated
-	transport Transport
-
 	schema *ytypes.Schema
 	id     uuid.UUID
 }
@@ -76,7 +73,7 @@ func (oc *OpenConfig) Unmarshal() func([]byte, []string, interface{}, ...ytypes.
 }
 
 // unmarshal parses a root or 1st level gNMI response to a go struct
-// Named return due to how recover works here
+// Named return to return appropriate recover error
 func unmarshal(bytes []byte, fields []string, goStruct interface{}, opt ...ytypes.UnmarshalOpt) (err error) {
 	defer func() {
 		if r := recover(); r != nil {
@@ -107,7 +104,7 @@ func unmarshal(bytes []byte, fields []string, goStruct interface{}, opt ...ytype
 }
 
 // iter walks down the provided paths and initializes the ygot.GoStruct. It only works for
-// the root level. Watch out for named returns here
+// the root level. Named returns to return appropriate recover error
 // TODO(mk): Fix deeper layers
 func iter(a ygot.GoStruct, fields []string) (b ygot.GoStruct, f string, err error) {
 	defer func() {

nucleus/southbound_test.go

@@ -13,18 +13,12 @@ import (
 
 func testSetupSbi() {
 	var err error
-	aristaUUID, err = uuid.Parse("d3795249-579c-4be7-8818-29f113cb86ee")
-	if err != nil {
-		log.Fatal(err)
-	}
-
 	ocUUID, err = uuid.Parse("5e252b70-38f2-4c99-a0bf-1b16af4d7e67")
 	if err != nil {
 		log.Fatal(err)
 	}
 }
 
-var aristaUUID uuid.UUID
 var ocUUID uuid.UUID
 
 func TestOpenConfig_Id(t *testing.T) {
@@ -41,7 +35,6 @@ func TestOpenConfig_Id(t *testing.T) {
 		{
 			name: "default",
 			fields: fields{
-				transport: nil,
 				schema:    nil,
 				id:        ocUUID,
 			},
@@ -51,7 +44,6 @@ func TestOpenConfig_Id(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			oc := &OpenConfig{
-				transport: tt.fields.transport,
 				schema:    tt.fields.schema,
 				id:        tt.fields.id,
 			}
@@ -64,7 +56,6 @@ func TestOpenConfig_Id(t *testing.T) {
 
 func TestOpenConfig_SbiIdentifier(t *testing.T) {
 	type fields struct {
-		transport Transport
 		schema    *ytypes.Schema
 		id        uuid.UUID
 	}
@@ -78,7 +69,6 @@ func TestOpenConfig_SbiIdentifier(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			oc := &OpenConfig{
-				transport: tt.fields.transport,
 				schema:    tt.fields.schema,
 				id:        tt.fields.id,
 			}
@@ -95,7 +85,6 @@ func TestOpenConfig_Schema(t *testing.T) {
 		t.Error(err)
 	}
 	type fields struct {
-		transport Transport
 		schema    *ytypes.Schema
 		id        uuid.UUID
 	}
@@ -109,7 +98,6 @@ func TestOpenConfig_Schema(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			oc := &OpenConfig{
-				transport: tt.fields.transport,
 				schema:    tt.fields.schema,
 				id:        tt.fields.id,
 			}

nucleus/store.go

@@ -2,8 +2,11 @@ package nucleus
 
 import (
 	"github.com/google/uuid"
+	log "github.com/sirupsen/logrus"
+	"reflect"
 )
 
+// Storable provides an interface for the controller's storage architecture.
 type Storable interface {
 	Id() uuid.UUID
 }
@@ -20,6 +23,10 @@ func (s store) add(item Storable) error {
 		return &ErrAlreadyExists{item: item}
 	}
 	s[item.Id()] = item
+	log.WithFields(log.Fields{
+		"type": reflect.TypeOf(item),
+		"uuid": item.Id(),
+	}).Info("storable was added")
 	return nil
 }
 
@@ -27,6 +34,9 @@ func (s store) get(id uuid.UUID) (Storable, error) {
 	if !s.exists(id) {
 		return nil, &ErrNotFound{id: id}
 	}
+	log.WithFields(log.Fields{
+		"uuid": id,
+	}).Info("storable was accessed")
 	return s[id], nil
 }
 
@@ -35,6 +45,9 @@ func (s store) delete(id uuid.UUID) error {
 		return &ErrNotFound{id: id}
 	}
 	delete(s, id)
+	log.WithFields(log.Fields{
+		"uuid": id,
+	}).Info("storable has been deleted")
 	return nil
 }
 
@@ -65,6 +78,9 @@ func (s sbiStore) get(id uuid.UUID) (SouthboundInterface, error) {
 			t: "SouthboundInterface",
 		}
 	}
+	log.WithFields(log.Fields{
+		"uuid": id,
+	}).Info("southbound interface was accessed")
 	return sbi, nil
 }
 
@@ -84,6 +100,9 @@ func (s pndStore) get(id uuid.UUID) (PrincipalNetworkDomain, error) {
 			t: "PrincipalNetworkDomain",
 		}
 	}
+	log.WithFields(log.Fields{
+		"uuid": id,
+	}).Info("principal network domain was accessed")
 	return pnd, nil
 }
 
@@ -103,5 +122,8 @@ func (s deviceStore) get(id uuid.UUID) (*Device, error) {
 			t: "Device",
 		}
 	}
+	log.WithFields(log.Fields{
+		"uuid": id,
+	}).Info("device was accessed")
 	return device, nil
 }