Skip to content

Commit

Permalink
Merge pull request #242 from dave-tucker/log-more
Browse files Browse the repository at this point in the history 
Add more logging to make debugging easier
  • Loading branch information
@dave-tucker
dave-tucker authored Oct 14, 2021
2 parents 52b0298 + d81f3de commit 8f9d582
Show file tree
Hide file tree
Showing 11 changed files with 95 additions and 68 deletions.
36 changes: 29 additions & 7 deletions cache/cache.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,12 +6,14 @@ import (
"encoding/gob"
"encoding/hex"
"fmt"
"log"
"os"
"reflect"
"strings"
"sync"

"log"

"github.com/go-logr/logr"
"github.com/go-logr/stdr"
"github.com/ovn-org/libovsdb/mapper"
"github.com/ovn-org/libovsdb/model"
"github.com/ovn-org/libovsdb/ovsdb"
Expand Down Expand Up @@ -434,18 +436,26 @@ type TableCache struct {
updates2 chan ovsdb.TableUpdates2
errorChan chan error
ovsdb.NotificationHandler
mutex sync.RWMutex
mutex sync.RWMutex
logger *logr.Logger
}

// Data is the type for data that can be prepopulated in the cache
type Data map[string]map[string]model.Model

// NewTableCache creates a new TableCache
func NewTableCache(schema *ovsdb.DatabaseSchema, dbModel *model.DBModel, data Data) (*TableCache, error) {
func NewTableCache(schema *ovsdb.DatabaseSchema, dbModel *model.DBModel, data Data, logger *logr.Logger) (*TableCache, error) {
if schema == nil || dbModel == nil {
return nil, fmt.Errorf("tablecache without databasemodel cannot be populated")
}
eventProcessor := newEventProcessor(bufferSize)
if logger == nil {
l := stdr.NewWithOptions(log.New(os.Stderr, "", log.LstdFlags), stdr.Options{LogCaller: stdr.All}).WithName("libovsdb/cache")
logger = &l
} else {
l := logger.WithName("cache")
logger = &l
}
eventProcessor := newEventProcessor(bufferSize, logger)
cache := make(map[string]*RowCache)
tableTypes := dbModel.Types()
for name, tableSchema := range schema.Tables {
Expand All @@ -471,6 +481,7 @@ func NewTableCache(schema *ovsdb.DatabaseSchema, dbModel *model.DBModel, data Da
updates: make(chan ovsdb.TableUpdates, bufferSize),
updates2: make(chan ovsdb.TableUpdates2, bufferSize),
errorChan: make(chan error),
logger: logger,
}, nil
}

Expand Down Expand Up @@ -553,13 +564,15 @@ func (t *TableCache) Populate(tableUpdates ovsdb.TableUpdates) error {
}
tCache := t.cache[table]
for uuid, row := range updates {
t.logger.V(5).Info("processing update for row", "uuid", uuid, "table", table)
if row.New != nil {
newModel, err := t.CreateModel(table, row.New, uuid)
if err != nil {
return err
}
if existing := tCache.Row(uuid); existing != nil {
if !reflect.DeepEqual(newModel, existing) {
t.logger.V(5).Info("updating row", "uuid", uuid, "old:", fmt.Sprintf("%+v", existing), "new", fmt.Sprintf("%+v", newModel))
if err := tCache.Update(uuid, newModel, false); err != nil {
return err
}
Expand All @@ -568,6 +581,7 @@ func (t *TableCache) Populate(tableUpdates ovsdb.TableUpdates) error {
// no diff
continue
}
t.logger.V(5).Info("creating row", "uuid", uuid, "model", fmt.Sprintf("%+v", newModel))
if err := tCache.Create(uuid, newModel, false); err != nil {
return err
}
Expand All @@ -578,6 +592,7 @@ func (t *TableCache) Populate(tableUpdates ovsdb.TableUpdates) error {
if err != nil {
return err
}
t.logger.V(5).Info("deleting row", "uuid", uuid, "model", fmt.Sprintf("%+v", oldModel))
if err := tCache.Delete(uuid); err != nil {
return err
}
Expand All @@ -600,12 +615,14 @@ func (t *TableCache) Populate2(tableUpdates ovsdb.TableUpdates2) error {
}
tCache := t.cache[table]
for uuid, row := range updates {
t.logger.V(5).Info("processing update for row", "uuid", uuid, "table", table)
switch {
case row.Initial != nil:
m, err := t.CreateModel(table, row.Initial, uuid)
if err != nil {
return err
}
t.logger.V(5).Info("creating row", "uuid", uuid, "model", fmt.Sprintf("%+v", m))
if err := tCache.Create(uuid, m, false); err != nil {
return err
}
Expand All @@ -615,6 +632,7 @@ func (t *TableCache) Populate2(tableUpdates ovsdb.TableUpdates2) error {
if err != nil {
return err
}
t.logger.V(5).Info("creating row", "uuid", uuid, "model", fmt.Sprintf("%+v", m))
if err := tCache.Create(uuid, m, false); err != nil {
return err
}
Expand All @@ -630,6 +648,7 @@ func (t *TableCache) Populate2(tableUpdates ovsdb.TableUpdates2) error {
return err
}
if !reflect.DeepEqual(modified, existing) {
t.logger.V(5).Info("updating row", "uuid", uuid, "old", fmt.Sprintf("%+v", existing), "new", fmt.Sprintf("%+v", modified))
if err := tCache.Update(uuid, modified, false); err != nil {
return err
}
Expand All @@ -644,6 +663,7 @@ func (t *TableCache) Populate2(tableUpdates ovsdb.TableUpdates2) error {
if m == nil {
panic(fmt.Errorf("row with uuid %s does not exist", uuid))
}
t.logger.V(5).Info("deleting row", "uuid", uuid, "model", fmt.Sprintf("%+v", m))
if err := tCache.Delete(uuid); err != nil {
return err
}
Expand Down Expand Up @@ -762,12 +782,14 @@ type eventProcessor struct {
// volume is very low (i.e only when AddEventHandler is called)
handlersMutex sync.Mutex
handlers []EventHandler
logger *logr.Logger
}

func newEventProcessor(capacity int) *eventProcessor {
func newEventProcessor(capacity int, logger *logr.Logger) *eventProcessor {
return &eventProcessor{
events: make(chan event, capacity),
handlers: []EventHandler{},
logger: logger,
}
}

Expand Down Expand Up @@ -796,7 +818,7 @@ func (e *eventProcessor) AddEvent(eventType string, table string, old model.Mode
// noop
return
default:
log.Print("libovsdb: dropping event because event buffer is full")
e.logger.V(0).Info("dropping event because event buffer is full")
}
}

Expand Down
30 changes: 16 additions & 14 deletions cache/cache_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ import (
"reflect"
"testing"

"github.com/go-logr/logr"
"github.com/ovn-org/libovsdb/mapper"
"github.com/ovn-org/libovsdb/model"
"github.com/ovn-org/libovsdb/ovsdb"
Expand Down Expand Up @@ -107,7 +108,7 @@ func TestRowCacheCreate(t *testing.T) {
testData := Data{
"Open_vSwitch": map[string]model.Model{"bar": &testModel{Foo: "bar"}},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.Nil(t, err)

tests := []struct {
Expand Down Expand Up @@ -194,7 +195,7 @@ func TestRowCacheCreateMultiIndex(t *testing.T) {
testData := Data{
"Open_vSwitch": map[string]model.Model{"bar": &testModel{Foo: "bar", Bar: "bar"}},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.Nil(t, err)
tests := []struct {
name string
Expand Down Expand Up @@ -289,7 +290,7 @@ func TestRowCacheUpdate(t *testing.T) {
"foobar": &testModel{Foo: "foobar"},
},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.Nil(t, err)

tests := []struct {
Expand Down Expand Up @@ -372,7 +373,7 @@ func TestRowCacheUpdateMultiIndex(t *testing.T) {
"foobar": &testModel{Foo: "foobar", Bar: "foobar"},
},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.Nil(t, err)

tests := []struct {
Expand Down Expand Up @@ -452,7 +453,7 @@ func TestRowCacheDelete(t *testing.T) {
"bar": &testModel{Foo: "bar"},
},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.Nil(t, err)

tests := []struct {
Expand Down Expand Up @@ -708,7 +709,7 @@ func TestTableCache_populate(t *testing.T) {
}
`), &schema)
assert.Nil(t, err)
tc, err := NewTableCache(&schema, db, nil)
tc, err := NewTableCache(&schema, db, nil, nil)
assert.Nil(t, err)

testRow := ovsdb.Row(map[string]interface{}{"_uuid": "test", "foo": "bar"})
Expand Down Expand Up @@ -776,7 +777,7 @@ func TestTableCachePopulate(t *testing.T) {
}
`), &schema)
assert.Nil(t, err)
tc, err := NewTableCache(&schema, db, nil)
tc, err := NewTableCache(&schema, db, nil, nil)
assert.Nil(t, err)

testRow := ovsdb.Row(map[string]interface{}{"_uuid": "test", "foo": "bar"})
Expand Down Expand Up @@ -843,7 +844,7 @@ func TestTableCachePopulate2(t *testing.T) {
}
`), &schema)
assert.Nil(t, err)
tc, err := NewTableCache(&schema, db, nil)
tc, err := NewTableCache(&schema, db, nil, nil)
assert.Nil(t, err)

testRow := ovsdb.Row(map[string]interface{}{"_uuid": "test", "foo": "bar"})
Expand Down Expand Up @@ -908,7 +909,8 @@ func TestTableCachePopulate2(t *testing.T) {
}

func TestEventProcessor_AddEvent(t *testing.T) {
ep := newEventProcessor(16)
logger := logr.Discard()
ep := newEventProcessor(16, &logger)
var events []event
for i := 0; i < 17; i++ {
events = append(events, event{
Expand Down Expand Up @@ -968,7 +970,7 @@ func TestIndex(t *testing.T) {
}
`), &schema)
assert.Nil(t, err)
tc, err := NewTableCache(&schema, db, nil)
tc, err := NewTableCache(&schema, db, nil, nil)
assert.Nil(t, err)
obj := &indexTestModel{
UUID: "test1",
Expand Down Expand Up @@ -1066,7 +1068,7 @@ func TestTableCacheRowByModelSingleIndex(t *testing.T) {
"bar": &testModel{Foo: "bar", Bar: "bar"},
},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.NoError(t, err)

t.Run("get foo by index", func(t *testing.T) {
Expand Down Expand Up @@ -1115,7 +1117,7 @@ func TestTableCacheRowByModelTwoIndexes(t *testing.T) {
"bar": &testModel{Foo: "bar", Bar: "bar"},
},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.NoError(t, err)

t.Run("get foo by Foo index", func(t *testing.T) {
Expand Down Expand Up @@ -1163,7 +1165,7 @@ func TestTableCacheRowByModelMultiIndex(t *testing.T) {
testData := Data{
"Open_vSwitch": map[string]model.Model{"foo": myFoo, "bar": &testModel{Foo: "bar", Bar: "bar"}},
}
tc, err := NewTableCache(&schema, db, testData)
tc, err := NewTableCache(&schema, db, testData, nil)
require.NoError(t, err)

t.Run("incomplete index", func(t *testing.T) {
Expand Down Expand Up @@ -1309,7 +1311,7 @@ func TestTableCacheApplyModifications(t *testing.T) {
}
`), &schema)
require.NoError(t, err)
tc, err := NewTableCache(&schema, db, nil)
tc, err := NewTableCache(&schema, db, nil, nil)
assert.Nil(t, err)
original := model.Clone(tt.base).(*testDBModel)
err = tc.ApplyModifications("Open_vSwitch", original, tt.update)
Expand Down
27 changes: 15 additions & 12 deletions client/api.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,9 +4,9 @@ import (
"encoding/json"
"errors"
"fmt"
"log"
"reflect"

"github.com/go-logr/logr"
"github.com/ovn-org/libovsdb/cache"
"github.com/ovn-org/libovsdb/mapper"
"github.com/ovn-org/libovsdb/model"
Expand Down Expand Up @@ -88,8 +88,9 @@ var ErrNotFound = errors.New("object not found")
// api struct implements both API and ConditionalAPI
// Where() can be used to create a ConditionalAPI api
type api struct {
cache *cache.TableCache
cond Conditional
cache *cache.TableCache
cond Conditional
logger *logr.Logger
}

// List populates a slice of Models given as parameter based on the configured Condition
Expand Down Expand Up @@ -148,17 +149,17 @@ func (a api) List(result interface{}) error {

// Where returns a conditionalAPI based on a Condition list
func (a api) Where(model model.Model, cond ...model.Condition) ConditionalAPI {
return newConditionalAPI(a.cache, a.conditionFromModel(false, model, cond...))
return newConditionalAPI(a.cache, a.conditionFromModel(false, model, cond...), a.logger)
}

// Where returns a conditionalAPI based on a Condition list
func (a api) WhereAll(model model.Model, cond ...model.Condition) ConditionalAPI {
return newConditionalAPI(a.cache, a.conditionFromModel(true, model, cond...))
return newConditionalAPI(a.cache, a.conditionFromModel(true, model, cond...), a.logger)
}

// Where returns a conditionalAPI based a Predicate
func (a api) WhereCache(predicate interface{}) ConditionalAPI {
return newConditionalAPI(a.cache, a.conditionFromFunc(predicate))
return newConditionalAPI(a.cache, a.conditionFromFunc(predicate), a.logger)
}

// Conditional interface implementation
Expand Down Expand Up @@ -364,7 +365,7 @@ func (a api) Update(model model.Model, fields ...interface{}) ([]ovsdb.Operation

for colName, column := range tableSchema.Columns {
if !column.Mutable() {
log.Printf("libovsdb: removing immutable field %s", colName)
a.logger.V(2).Info("removing immutable field", "name", colName)
delete(row, colName)
}
}
Expand Down Expand Up @@ -448,16 +449,18 @@ func (a api) getTableFromFunc(predicate interface{}) (string, error) {
}

// newAPI returns a new API to interact with the database
func newAPI(cache *cache.TableCache) API {
func newAPI(cache *cache.TableCache, logger *logr.Logger) API {
return api{
cache: cache,
cache: cache,
logger: logger,
}
}

// newConditionalAPI returns a new ConditionalAPI to interact with the database
func newConditionalAPI(cache *cache.TableCache, cond Conditional) ConditionalAPI {
func newConditionalAPI(cache *cache.TableCache, cond Conditional, logger *logr.Logger) ConditionalAPI {
return api{
cache: cache,
cond: cond,
cache: cache,
cond: cond,
logger: logger,
}
}
Loading

0 comments on commit 8f9d582

Please sign in to comment.