From fce2ea693d709afae52477c195d4a84f36bb8f05 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Fri, 11 Mar 2022 16:45:44 -0500 Subject: [PATCH 01/17] Use multiple value insert for pins, and correct enablement for PSQL Signed-off-by: Peter Broadhurst --- internal/database/postgres/postgres.go | 1 + internal/database/sqlcommon/pin_sql.go | 74 ++++++++++++++++----- internal/database/sqlcommon/pin_sql_test.go | 55 +++++++++++++++ internal/database/sqlcommon/sqlcommon.go | 28 ++++++-- internal/events/batch_pin_complete.go | 17 ++++- internal/events/batch_pin_complete_test.go | 4 +- mocks/databasemocks/plugin.go | 14 ++++ pkg/database/plugin.go | 3 + test/e2e/tokens_test.go | 1 + 9 files changed, 172 insertions(+), 25 deletions(-) diff --git a/internal/database/postgres/postgres.go b/internal/database/postgres/postgres.go index 115f4c5795..6cb99e5e1f 100644 --- a/internal/database/postgres/postgres.go +++ b/internal/database/postgres/postgres.go @@ -57,6 +57,7 @@ func (psql *Postgres) Features() sqlcommon.SQLFeatures { features.ExclusiveTableLockSQL = func(table string) string { return fmt.Sprintf(`LOCK TABLE "%s" IN EXCLUSIVE MODE;`, table) } + features.MultiRowInsert = true return features } diff --git a/internal/database/sqlcommon/pin_sql.go b/internal/database/sqlcommon/pin_sql.go index 8cd2008b4d..7e9a7da92a 100644 --- a/internal/database/sqlcommon/pin_sql.go +++ b/internal/database/sqlcommon/pin_sql.go @@ -74,22 +74,7 @@ func (s *SQLCommon) UpsertPin(ctx context.Context, pin *fftypes.Pin) (err error) log.L(ctx).Debugf("Existing pin returned at sequence %d", pin.Sequence) } else { pinRows.Close() - if pin.Sequence, err = s.insertTx(ctx, tx, - sq.Insert("pins"). - Columns(pinColumns...). - Values( - pin.Masked, - pin.Hash, - pin.Batch, - pin.Index, - pin.Signer, - pin.Dispatched, - pin.Created, - ), - func() { - s.callbacks.OrderedCollectionEvent(database.CollectionPins, fftypes.ChangeEventTypeCreated, pin.Sequence) - }, - ); err != nil { + if err = s.attemptPinInsert(ctx, tx, pin); err != nil { return err } @@ -98,6 +83,63 @@ func (s *SQLCommon) UpsertPin(ctx context.Context, pin *fftypes.Pin) (err error) return s.commitTx(ctx, tx, autoCommit) } +func (s *SQLCommon) attemptPinInsert(ctx context.Context, tx *txWrapper, pin *fftypes.Pin) (err error) { + pin.Sequence, err = s.insertTx(ctx, tx, + s.setPinInsertValues(sq.Insert("pins").Columns(pinColumns...), pin), + func() { + log.L(ctx).Debugf("Triggering creation event for pin %d", pin.Sequence) + s.callbacks.OrderedCollectionEvent(database.CollectionPins, fftypes.ChangeEventTypeCreated, pin.Sequence) + }, + ) + return err +} + +func (s *SQLCommon) setPinInsertValues(query sq.InsertBuilder, pin *fftypes.Pin) sq.InsertBuilder { + return query.Values( + pin.Masked, + pin.Hash, + pin.Batch, + pin.Index, + pin.Signer, + pin.Dispatched, + pin.Created, + ) +} + +func (s *SQLCommon) InsertPins(ctx context.Context, pins []*fftypes.Pin) error { + ctx, tx, autoCommit, err := s.beginOrUseTx(ctx) + if err != nil { + return err + } + defer s.rollbackTx(ctx, tx, autoCommit) + + if s.features.MultiRowInsert { + query := sq.Insert("pins").Columns(pinColumns...) + for _, pin := range pins { + query = s.setPinInsertValues(query, pin) + } + sequences := make([]int64, len(pins)) + err := s.insertTxRows(ctx, tx, query, func() { + for i, pin := range pins { + pin.Sequence = sequences[i] + s.callbacks.OrderedCollectionEvent(database.CollectionPins, fftypes.ChangeEventTypeCreated, pin.Sequence) + } + }, sequences, true /* we want the caller to be able to retry with individual upserts */) + if err != nil { + return err + } + } else { + // Fall back to individual inserts grouped in a TX + for _, pin := range pins { + if err := s.attemptPinInsert(ctx, tx, pin); err != nil { + return err + } + } + } + + return s.commitTx(ctx, tx, autoCommit) +} + func (s *SQLCommon) pinResult(ctx context.Context, row *sql.Rows) (*fftypes.Pin, error) { pin := fftypes.Pin{} err := row.Scan( diff --git a/internal/database/sqlcommon/pin_sql_test.go b/internal/database/sqlcommon/pin_sql_test.go index b2510247fa..2c98c5b1b3 100644 --- a/internal/database/sqlcommon/pin_sql_test.go +++ b/internal/database/sqlcommon/pin_sql_test.go @@ -141,6 +141,61 @@ func TestUpsertPinFailCommit(t *testing.T) { assert.NoError(t, mock.ExpectationsWereMet()) } +func TestInsertPinsBeginFail(t *testing.T) { + s, mock := newMockProvider().init() + mock.ExpectBegin().WillReturnError(fmt.Errorf("pop")) + err := s.InsertPins(context.Background(), []*fftypes.Pin{}) + assert.Regexp(t, "FF10114", err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + +func TestInsertPinsMultiRowOK(t *testing.T) { + s, mock := newMockProvider().init() + s.features.MultiRowInsert = true + s.fakePSQLInsert = true + + pin1 := &fftypes.Pin{Hash: fftypes.NewRandB32()} + pin2 := &fftypes.Pin{Hash: fftypes.NewRandB32()} + s.callbacks.On("OrderedCollectionEvent", database.CollectionPins, fftypes.ChangeEventTypeCreated, int64(1001)) + s.callbacks.On("OrderedCollectionEvent", database.CollectionPins, fftypes.ChangeEventTypeCreated, int64(1002)) + + mock.ExpectBegin() + mock.ExpectQuery("INSERT.*").WillReturnRows(sqlmock.NewRows([]string{sequenceColumn}). + AddRow(int64(1001)). + AddRow(int64(1002)), + ) + mock.ExpectCommit() + err := s.InsertPins(context.Background(), []*fftypes.Pin{pin1, pin2}) + assert.NoError(t, err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + +func TestInsertPinsMultiRowFail(t *testing.T) { + s, mock := newMockProvider().init() + s.features.MultiRowInsert = true + s.fakePSQLInsert = true + pin1 := &fftypes.Pin{Hash: fftypes.NewRandB32()} + mock.ExpectBegin() + mock.ExpectQuery("INSERT.*").WillReturnError(fmt.Errorf("pop")) + err := s.InsertPins(context.Background(), []*fftypes.Pin{pin1}) + assert.Regexp(t, "FF10116", err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + +func TestInsertPinsSingleRowFail(t *testing.T) { + s, mock := newMockProvider().init() + pin1 := &fftypes.Pin{Hash: fftypes.NewRandB32()} + mock.ExpectBegin() + mock.ExpectExec("INSERT.*").WillReturnError(fmt.Errorf("pop")) + err := s.InsertPins(context.Background(), []*fftypes.Pin{pin1}) + assert.Regexp(t, "FF10116", err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + func TestGetPinQueryFail(t *testing.T) { s, mock := newMockProvider().init() mock.ExpectQuery("SELECT .*").WillReturnError(fmt.Errorf("pop")) diff --git a/internal/database/sqlcommon/sqlcommon.go b/internal/database/sqlcommon/sqlcommon.go index 8e3cec5152..f725787bd9 100644 --- a/internal/database/sqlcommon/sqlcommon.go +++ b/internal/database/sqlcommon/sqlcommon.go @@ -20,6 +20,7 @@ import ( "context" "database/sql" "fmt" + "strings" sq "github.com/Masterminds/squirrel" "github.com/golang-migrate/migrate/v4" @@ -51,6 +52,21 @@ type txWrapper struct { tableLocks []string } +func shortenSQL(sqlString string) string { + buff := strings.Builder{} + spaceCount := 0 + for _, c := range sqlString { + if c == ' ' { + spaceCount++ + if spaceCount >= 3 { + break + } + } + buff.WriteRune(c) + } + return buff.String() +} + func (s *SQLCommon) Init(ctx context.Context, provider Provider, prefix config.Prefix, callbacks database.Callbacks, capabilities *database.Capabilities) (err error) { s.capabilities = capabilities s.callbacks = callbacks @@ -176,7 +192,7 @@ func (s *SQLCommon) queryTx(ctx context.Context, tx *txWrapper, q sq.SelectBuild if err != nil { return nil, tx, i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> query: %s`, sqlQuery) + l.Debugf(`SQL-> query: %s`, shortenSQL(sqlQuery)) l.Tracef(`SQL-> query args: %+v`, args) var rows *sql.Rows if tx != nil { @@ -212,7 +228,7 @@ func (s *SQLCommon) countQuery(ctx context.Context, tx *txWrapper, tableName str if err != nil { return count, i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> count query: %s`, sqlQuery) + l.Debugf(`SQL-> count query: %s`, shortenSQL(sqlQuery)) l.Tracef(`SQL-> count query args: %+v`, args) var rows *sql.Rows if tx != nil { @@ -265,7 +281,7 @@ func (s *SQLCommon) insertTxRows(ctx context.Context, tx *txWrapper, q sq.Insert if err != nil { return i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> insert: %s`, sqlQuery) + l.Debugf(`SQL-> insert: %s`, shortenSQL(sqlQuery)) l.Tracef(`SQL-> insert args: %+v`, args) if useQuery { result, err := tx.sqlTX.QueryContext(ctx, sqlQuery, args...) @@ -312,7 +328,7 @@ func (s *SQLCommon) deleteTx(ctx context.Context, tx *txWrapper, q sq.DeleteBuil if err != nil { return i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> delete: %s`, sqlQuery) + l.Debugf(`SQL-> delete: %s`, shortenSQL(sqlQuery)) l.Tracef(`SQL-> delete args: %+v`, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { @@ -337,7 +353,7 @@ func (s *SQLCommon) updateTx(ctx context.Context, tx *txWrapper, q sq.UpdateBuil if err != nil { return -1, i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> update: %s`, sqlQuery) + l.Debugf(`SQL-> update: %s`, shortenSQL(sqlQuery)) l.Tracef(`SQL-> update args: %+v`, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { @@ -375,7 +391,7 @@ func (s *SQLCommon) lockTableExclusiveTx(ctx context.Context, tx *txWrapper, tab if s.features.ExclusiveTableLockSQL != nil && !tx.tableIsLocked(table) { sqlQuery := s.features.ExclusiveTableLockSQL(table) - l.Debugf(`SQL-> lock: %s`, sqlQuery) + l.Debugf(`SQL-> lock: %s`, shortenSQL(sqlQuery)) _, err := tx.sqlTX.ExecContext(ctx, sqlQuery) if err != nil { l.Errorf(`SQL lock failed: %s sql=[ %s ]`, err, sqlQuery) diff --git a/internal/events/batch_pin_complete.go b/internal/events/batch_pin_complete.go index b85eb3af86..19e8144e4d 100644 --- a/internal/events/batch_pin_complete.go +++ b/internal/events/batch_pin_complete.go @@ -77,15 +77,28 @@ func (em *eventManager) persistBatchTransaction(ctx context.Context, batchPin *b } func (em *eventManager) persistContexts(ctx context.Context, batchPin *blockchain.BatchPin, signingKey *fftypes.VerifierRef, private bool) error { + pins := make([]*fftypes.Pin, len(batchPin.Contexts)) for idx, hash := range batchPin.Contexts { - if err := em.database.UpsertPin(ctx, &fftypes.Pin{ + pins[idx] = &fftypes.Pin{ Masked: private, Hash: hash, Batch: batchPin.BatchID, Index: int64(idx), Signer: signingKey.Value, // We don't store the type as we can infer that from the blockchain Created: fftypes.Now(), - }); err != nil { + } + } + + // First attempt a single batch insert + err := em.database.InsertPins(ctx, pins) + if err == nil { + return nil + } + log.L(ctx).Warnf("Batch insert of pins failed - assuming replay and performing upserts: %s", err) + + // Fall back to an upsert + for _, pin := range pins { + if err := em.database.UpsertPin(ctx, pin); err != nil { return err } } diff --git a/internal/events/batch_pin_complete_test.go b/internal/events/batch_pin_complete_test.go index ec3a8a687e..15934090bc 100644 --- a/internal/events/batch_pin_complete_test.go +++ b/internal/events/batch_pin_complete_test.go @@ -140,7 +140,7 @@ func TestBatchPinCompleteOkBroadcast(t *testing.T) { mdi.On("InsertEvent", mock.Anything, mock.MatchedBy(func(e *fftypes.Event) bool { return e.Type == fftypes.EventTypeBlockchainEventReceived })).Return(nil).Times(2) - mdi.On("UpsertPin", mock.Anything, mock.Anything).Return(nil).Once() + mdi.On("InsertPins", mock.Anything, mock.Anything).Return(nil).Once() mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(nil).Once() mbi := &blockchainmocks.Plugin{} @@ -198,6 +198,7 @@ func TestBatchPinCompleteOkPrivate(t *testing.T) { mdi := em.database.(*databasemocks.Plugin) mdi.On("RunAsGroup", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertPins", mock.Anything, mock.Anything).Return(fmt.Errorf("These pins have been seen before")) // simulate replay fallback mdi.On("UpsertPin", mock.Anything, mock.Anything).Return(nil) mbi := &blockchainmocks.Plugin{} @@ -764,6 +765,7 @@ func TestPersistContextsFail(t *testing.T) { defer cancel() mdi := em.database.(*databasemocks.Plugin) + mdi.On("InsertPins", mock.Anything, mock.Anything).Return(fmt.Errorf("duplicate pins")) mdi.On("UpsertPin", mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) err := em.persistContexts(em.ctx, &blockchain.BatchPin{ diff --git a/mocks/databasemocks/plugin.go b/mocks/databasemocks/plugin.go index 0bfbcd2189..e15b3dc4e7 100644 --- a/mocks/databasemocks/plugin.go +++ b/mocks/databasemocks/plugin.go @@ -2291,6 +2291,20 @@ func (_m *Plugin) InsertOperation(ctx context.Context, operation *fftypes.Operat return r0 } +// InsertPins provides a mock function with given fields: ctx, pins +func (_m *Plugin) InsertPins(ctx context.Context, pins []*fftypes.Pin) error { + ret := _m.Called(ctx, pins) + + var r0 error + if rf, ok := ret.Get(0).(func(context.Context, []*fftypes.Pin) error); ok { + r0 = rf(ctx, pins) + } else { + r0 = ret.Error(0) + } + + return r0 +} + // InsertTransaction provides a mock function with given fields: ctx, data func (_m *Plugin) InsertTransaction(ctx context.Context, data *fftypes.Transaction) error { ret := _m.Called(ctx, data) diff --git a/pkg/database/plugin.go b/pkg/database/plugin.go index 427b224247..c19d3ef63d 100644 --- a/pkg/database/plugin.go +++ b/pkg/database/plugin.go @@ -185,6 +185,9 @@ type iOffsetCollection interface { } type iPinCollection interface { + // InsertPins - Inserts a list of pins - fails if they already exist, so caller can fall back to UpsertPin individually + InsertPins(ctx context.Context, pins []*fftypes.Pin) (err error) + // UpsertPin - Will insert a pin at the end of the sequence, unless the batch+hash+index sequence already exists UpsertPin(ctx context.Context, parked *fftypes.Pin) (err error) diff --git a/test/e2e/tokens_test.go b/test/e2e/tokens_test.go index 3e42b7db7a..4b5be2ffd9 100644 --- a/test/e2e/tokens_test.go +++ b/test/e2e/tokens_test.go @@ -75,6 +75,7 @@ func (suite *TokensTestSuite) TestE2EFungibleTokensAsync() { Operator: suite.testState.org2key.Value, Approved: true, }, + Pool: poolName, } approvalOut := TokenApproval(suite.T(), suite.testState.client1, approval, false) From 041005cc257c9d2023181037e3f1a7ed35797388 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Fri, 11 Mar 2022 17:07:36 -0500 Subject: [PATCH 02/17] Retry longer delay now we have confidence of applying multi-row Signed-off-by: Peter Broadhurst --- internal/config/config.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/config/config.go b/internal/config/config.go index f435753d0c..1c0bb9b40c 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -351,7 +351,7 @@ func Reset() { viper.SetDefault(string(MessageCacheSize), "50Mb") viper.SetDefault(string(MessageCacheTTL), "5m") viper.SetDefault(string(MessageWriterBatchMaxInserts), 200) - viper.SetDefault(string(MessageWriterBatchTimeout), "25ms") + viper.SetDefault(string(MessageWriterBatchTimeout), "50ms") viper.SetDefault(string(MessageWriterCount), 5) viper.SetDefault(string(NamespacesDefault), "default") viper.SetDefault(string(NamespacesPredefined), fftypes.JSONObjectArray{{"name": "default", "description": "Default predefined namespace"}}) From 4e0a86d8e584b958ff25d9ac25d19d47899b81cd Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Fri, 11 Mar 2022 17:32:45 -0500 Subject: [PATCH 03/17] Throughput optimize for events to avoid DB polling overhead Signed-off-by: Peter Broadhurst --- internal/config/config.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/config/config.go b/internal/config/config.go index 1c0bb9b40c..f6b7bb9a0a 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -333,7 +333,7 @@ func Reset() { viper.SetDefault(string(EventAggregatorOpCorrelationRetries), 3) viper.SetDefault(string(EventDBEventsBufferSize), 100) viper.SetDefault(string(EventDispatcherBufferLength), 5) - viper.SetDefault(string(EventDispatcherBatchTimeout), "0") + viper.SetDefault(string(EventDispatcherBatchTimeout), "250ms") viper.SetDefault(string(EventDispatcherPollTimeout), "30s") viper.SetDefault(string(EventTransportsEnabled), []string{"websockets", "webhooks"}) viper.SetDefault(string(EventTransportsDefault), "websockets") From 5c4d55b990ca448ad393627d77146fe4faebb28f Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sat, 12 Mar 2022 22:54:28 -0500 Subject: [PATCH 04/17] Diagnose cache misses Signed-off-by: Peter Broadhurst --- internal/data/data_manager.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/internal/data/data_manager.go b/internal/data/data_manager.go index 309afec8ba..991fe9dca1 100644 --- a/internal/data/data_manager.go +++ b/internal/data/data_manager.go @@ -220,6 +220,7 @@ func (dm *dataManager) dataLookupAndCache(ctx context.Context, msg *fftypes.Mess func (dm *dataManager) queryMessageCache(ctx context.Context, id *fftypes.UUID, options ...CacheReadOption) *messageCacheEntry { cached := dm.messageCache.Get(id.String()) if cached == nil { + log.L(context.Background()).Debugf("Cache miss for message %s", id) return nil } mce := cached.Value().(*messageCacheEntry) @@ -228,23 +229,23 @@ func (dm *dataManager) queryMessageCache(ctx context.Context, id *fftypes.UUID, case CRORequirePublicBlobRefs: for idx, d := range mce.data { if d.Blob != nil && d.Blob.Public == "" { - log.L(ctx).Debugf("Cache entry for data %d (%s) in message %s is missing public blob ref", idx, d.ID, mce.msg.Header.ID) + log.L(ctx).Debugf("Cache miss for message %s - data %d (%s) is missing public blob ref", idx, d.ID, mce.msg.Header.ID) return nil } } case CRORequirePins: if len(mce.msg.Header.Topics) != len(mce.msg.Pins) { - log.L(ctx).Debugf("Cache entry for message %s is missing pins", mce.msg.Header.ID) + log.L(ctx).Debugf("Cache miss for message %s - missing pins (topics=%d,pins=%d)", mce.msg.Header.ID, len(mce.msg.Header.Topics), len(mce.msg.Pins)) return nil } case CRORequireBatchID: if mce.msg.BatchID == nil { - log.L(ctx).Debugf("Cache entry for message %s is missing batch ID", mce.msg.Header.ID) + log.L(ctx).Debugf("Cache miss for message %s - missing batch ID", mce.msg.Header.ID) return nil } } } - log.L(ctx).Debugf("Returning msg %s from cache", id) + log.L(ctx).Debugf("Cache hit for message %s", id) cached.Extend(dm.messageCacheTTL) return mce } @@ -258,6 +259,7 @@ func (dm *dataManager) UpdateMessageCache(msg *fftypes.Message, data fftypes.Dat size: msg.EstimateSize(true), } dm.messageCache.Set(msg.Header.ID.String(), cacheEntry, dm.messageCacheTTL) + log.L(context.Background()).Debugf("Added to cache: %s (topics=%d,pins=%d)", msg.Header.ID.String(), len(msg.Header.Topics), len(msg.Pins)) } // UpdateMessageIfCached is used in order to notify the fields of a message that are not initially filled in, have been filled in. From 364e8ae6c37b9f423485c2c9059213d6de395600 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sat, 12 Mar 2022 23:47:04 -0500 Subject: [PATCH 05/17] Only query id+sequence when reading pages in batch manager Signed-off-by: Peter Broadhurst --- internal/batch/batch_manager.go | 38 ++-- internal/batch/batch_manager_test.go | 164 ++++++++---------- internal/data/data_manager.go | 2 +- internal/database/sqlcommon/message_sql.go | 28 +++ .../database/sqlcommon/message_sql_test.go | 32 ++++ mocks/databasemocks/plugin.go | 23 +++ pkg/database/plugin.go | 3 + pkg/fftypes/id_and_sequence.go | 23 +++ 8 files changed, 204 insertions(+), 109 deletions(-) create mode 100644 pkg/fftypes/id_and_sequence.go diff --git a/internal/batch/batch_manager.go b/internal/batch/batch_manager.go index 7565cd73f4..2330623f24 100644 --- a/internal/batch/batch_manager.go +++ b/internal/batch/batch_manager.go @@ -187,34 +187,34 @@ func (bm *batchManager) getProcessor(txType fftypes.TransactionType, msgType fft return processor, nil } -func (bm *batchManager) assembleMessageData(msg *fftypes.Message) (retData fftypes.DataArray, err error) { +func (bm *batchManager) assembleMessageData(id *fftypes.UUID) (msg *fftypes.Message, retData fftypes.DataArray, err error) { var foundAll = false - err = bm.retry.Do(bm.ctx, fmt.Sprintf("assemble message %s data", msg.Header.ID), func(attempt int) (retry bool, err error) { - retData, foundAll, err = bm.data.GetMessageDataCached(bm.ctx, msg) + err = bm.retry.Do(bm.ctx, "retrieve message", func(attempt int) (retry bool, err error) { + msg, retData, foundAll, err = bm.data.GetMessageWithDataCached(bm.ctx, id) // continual retry for persistence error (distinct from not-found) return true, err }) if err != nil { - return nil, err + return nil, nil, err } if !foundAll { - return nil, i18n.NewError(bm.ctx, i18n.MsgDataNotFound, msg.Header.ID) + return nil, nil, i18n.NewError(bm.ctx, i18n.MsgDataNotFound, id) } - return retData, nil + return msg, retData, nil } -func (bm *batchManager) readPage() ([]*fftypes.Message, error) { +func (bm *batchManager) readPage() ([]*fftypes.IDAndSequence, error) { - var msgs []*fftypes.Message + var ids []*fftypes.IDAndSequence err := bm.retry.Do(bm.ctx, "retrieve messages", func(attempt int) (retry bool, err error) { fb := database.MessageQueryFactory.NewFilterLimit(bm.ctx, bm.readPageSize) - msgs, _, err = bm.database.GetMessages(bm.ctx, fb.And( + ids, err = bm.database.GetMessageIDs(bm.ctx, fb.And( fb.Gt("sequence", bm.readOffset), fb.Eq("state", fftypes.MessageStateReady), ).Sort("sequence").Limit(bm.readPageSize)) return true, err }) - return msgs, err + return ids, err } func (bm *batchManager) messageSequencer() { @@ -227,24 +227,24 @@ func (bm *batchManager) messageSequencer() { bm.reapQuiescing() // Read messages from the DB - in an error condition we retry until success, or a closed context - msgs, err := bm.readPage() + msgIDs, err := bm.readPage() if err != nil { l.Debugf("Exiting: %s", err) return } - batchWasFull := (uint64(len(msgs)) == bm.readPageSize) + batchWasFull := (uint64(len(msgIDs)) == bm.readPageSize) - if len(msgs) > 0 { - for _, msg := range msgs { - processor, err := bm.getProcessor(msg.Header.TxType, msg.Header.Type, msg.Header.Group, msg.Header.Namespace, &msg.Header.SignerRef) + if len(msgIDs) > 0 { + for _, id := range msgIDs { + msg, data, err := bm.assembleMessageData(&id.ID) if err != nil { - l.Errorf("Failed to dispatch message %s: %s", msg.Header.ID, err) + l.Errorf("Failed to retrieve message data for %s: %s", id.ID, err) continue } - data, err := bm.assembleMessageData(msg) + processor, err := bm.getProcessor(msg.Header.TxType, msg.Header.Type, msg.Header.Group, msg.Header.Namespace, &msg.Header.SignerRef) if err != nil { - l.Errorf("Failed to retrieve message data for %s: %s", msg.Header.ID, err) + l.Errorf("Failed to dispatch message %s: %s", msg.Header.ID, err) continue } @@ -252,7 +252,7 @@ func (bm *batchManager) messageSequencer() { } // Next time round only read after the messages we just processed (unless we get a tap to rewind) - bm.readOffset = msgs[len(msgs)-1].Sequence + bm.readOffset = msgIDs[len(msgIDs)-1].Sequence } // Wait to be woken again diff --git a/internal/batch/batch_manager_test.go b/internal/batch/batch_manager_test.go index 27bbc328e1..95a99e2e3f 100644 --- a/internal/batch/batch_manager_test.go +++ b/internal/batch/batch_manager_test.go @@ -99,10 +99,10 @@ func TestE2EDispatchBroadcast(t *testing.T) { ID: dataID1, Hash: dataHash, } - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{data}, true, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{data}, true, nil) mdm.On("UpdateMessageIfCached", mock.Anything, mock.Anything).Return() - mdi.On("GetMessages", mock.Anything, mock.Anything).Return([]*fftypes.Message{msg}, nil, nil).Once() - mdi.On("GetMessages", mock.Anything, mock.Anything).Return([]*fftypes.Message{}, nil, nil) + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil).Once() + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{}, nil) mdi.On("UpsertBatch", mock.Anything, mock.Anything, mock.Anything).Return(nil) mdi.On("UpdateBatch", mock.Anything, mock.Anything, mock.Anything).Return(nil) mdi.On("UpdateMessage", mock.Anything, mock.Anything, mock.Anything).Return(nil) // pins @@ -218,10 +218,10 @@ func TestE2EDispatchPrivateUnpinned(t *testing.T) { ID: dataID1, Hash: dataHash, } - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{data}, true, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{data}, true, nil) mdm.On("UpdateMessageIfCached", mock.Anything, mock.Anything).Return() - mdi.On("GetMessages", mock.Anything, mock.Anything).Return([]*fftypes.Message{msg}, nil, nil).Once() - mdi.On("GetMessages", mock.Anything, mock.Anything).Return([]*fftypes.Message{}, nil, nil) + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil).Once() + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{}, nil) mdi.On("UpdateMessage", mock.Anything, mock.Anything, mock.Anything).Return(nil) // pins mdi.On("UpsertBatch", mock.Anything, mock.Anything, mock.Anything).Return(nil) mdi.On("UpdateBatch", mock.Anything, mock.Anything, mock.Anything).Return(nil) @@ -275,9 +275,13 @@ func TestDispatchUnknownType(t *testing.T) { bmi, _ := NewBatchManager(ctx, mni, mdi, mdm, txHelper) bm := bmi.(*batchManager) - msg := &fftypes.Message{} - mdi.On("GetMessages", mock.Anything, mock.Anything).Return([]*fftypes.Message{msg}, nil, nil).Once() - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{}, true, nil) + msg := &fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + }, + } + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil).Once() + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{}, true, nil) err := bm.Start() assert.NoError(t, err) @@ -309,7 +313,7 @@ func TestMessageSequencerCancelledContext(t *testing.T) { mdm := &datamocks.Manager{} mni := &sysmessagingmocks.LocalNodeInfo{} txHelper := txcommon.NewTransactionHelper(mdi, mdm) - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything).Return(nil, nil, fmt.Errorf("pop")) + mdi.On("GetMessageIDs", mock.Anything, mock.Anything).Return(nil, fmt.Errorf("pop")).Once() bm, _ := NewBatchManager(context.Background(), mni, mdi, mdm, txHelper) defer bm.Close() ctx, cancel := context.WithCancel(context.Background()) @@ -333,25 +337,25 @@ func TestMessageSequencerMissingMessageData(t *testing.T) { ) dataID := fftypes.NewUUID() - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything). - Return([]*fftypes.Message{ - { - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - Type: fftypes.MessageTypeBroadcast, - Namespace: "ns1", - TxType: fftypes.TransactionTypeNone, - }, - Data: []*fftypes.DataRef{ - {ID: dataID}, - }}, - }, nil, nil). + msg := &fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + Type: fftypes.MessageTypeBroadcast, + Namespace: "ns1", + TxType: fftypes.TransactionTypeNone, + }, + Data: []*fftypes.DataRef{ + {ID: dataID}, + }} + + mdi.On("GetMessageIDs", mock.Anything, mock.Anything, mock.Anything). + Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil, nil). Run(func(args mock.Arguments) { bm.Close() }). Once() - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.Message{}, nil, nil) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{}, false, nil) + mdi.On("GetMessageIDs", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{}, nil, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{}, false, nil) bm.(*batchManager).messageSequencer() @@ -377,19 +381,19 @@ func TestMessageSequencerUpdateMessagesFail(t *testing.T) { ) dataID := fftypes.NewUUID() - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.Message{ - { - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - TxType: fftypes.TransactionTypeBatchPin, - Type: fftypes.MessageTypeBroadcast, - Namespace: "ns1", - }, - Data: []*fftypes.DataRef{ - {ID: dataID}, - }}, - }, nil, nil) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{{ID: dataID}}, true, nil) + msg := &fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + TxType: fftypes.TransactionTypeBatchPin, + Type: fftypes.MessageTypeBroadcast, + Namespace: "ns1", + }, + Data: []*fftypes.DataRef{ + {ID: dataID}, + }, + } + mdi.On("GetMessageIDs", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{{ID: dataID}}, true, nil) mdm.On("UpdateMessageIfCached", mock.Anything, mock.Anything).Return() mdi.On("InsertTransaction", mock.Anything, mock.Anything).Return(nil) mdi.On("InsertEvent", mock.Anything, mock.Anything).Return(nil) // transaction submit @@ -432,19 +436,19 @@ func TestMessageSequencerDispatchFail(t *testing.T) { ) dataID := fftypes.NewUUID() - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.Message{ - { - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - TxType: fftypes.TransactionTypeBatchPin, - Type: fftypes.MessageTypeBroadcast, - Namespace: "ns1", - }, - Data: []*fftypes.DataRef{ - {ID: dataID}, - }}, - }, nil, nil) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{{ID: dataID}}, true, nil) + msg := &fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + TxType: fftypes.TransactionTypeBatchPin, + Type: fftypes.MessageTypeBroadcast, + Namespace: "ns1", + }, + Data: []*fftypes.DataRef{ + {ID: dataID}, + }, + } + mdi.On("GetMessageIDs", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{{ID: dataID}}, true, nil) mdi.On("RunAsGroup", mock.Anything, mock.Anything, mock.Anything).Return(nil) bm.(*batchManager).messageSequencer() @@ -472,19 +476,19 @@ func TestMessageSequencerUpdateBatchFail(t *testing.T) { ) dataID := fftypes.NewUUID() - mdi.On("GetMessages", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.Message{ - { - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - TxType: fftypes.TransactionTypeBatchPin, - Type: fftypes.MessageTypeBroadcast, - Namespace: "ns1", - }, - Data: []*fftypes.DataRef{ - {ID: dataID}, - }}, - }, nil, nil) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(fftypes.DataArray{{ID: dataID}}, true, nil) + msg := &fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + TxType: fftypes.TransactionTypeBatchPin, + Type: fftypes.MessageTypeBroadcast, + Namespace: "ns1", + }, + Data: []*fftypes.DataRef{ + {ID: dataID}, + }, + } + mdi.On("GetMessageIDs", mock.Anything, mock.Anything, mock.Anything).Return([]*fftypes.IDAndSequence{{ID: *msg.Header.ID}}, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(msg, fftypes.DataArray{{ID: dataID}}, true, nil) mdi.On("UpsertBatch", mock.Anything, mock.Anything, mock.Anything).Return(fmt.Errorf("fizzle")) rag := mdi.On("RunAsGroup", mock.Anything, mock.Anything, mock.Anything) rag.RunFn = func(a mock.Arguments) { @@ -539,13 +543,8 @@ func TestAssembleMessageDataNilData(t *testing.T) { txHelper := txcommon.NewTransactionHelper(mdi, mdm) bm, _ := NewBatchManager(context.Background(), mni, mdi, mdm, txHelper) bm.Close() - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(nil, false, nil) - _, err := bm.(*batchManager).assembleMessageData(&fftypes.Message{ - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - }, - Data: fftypes.DataRefs{{ID: nil}}, - }) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(nil, nil, false, nil) + _, _, err := bm.(*batchManager).assembleMessageData(fftypes.NewUUID()) assert.Regexp(t, "FF10133", err) } @@ -555,16 +554,10 @@ func TestGetMessageDataFail(t *testing.T) { mni := &sysmessagingmocks.LocalNodeInfo{} txHelper := txcommon.NewTransactionHelper(mdi, mdm) bm, _ := NewBatchManager(context.Background(), mni, mdi, mdm, txHelper) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(nil, false, fmt.Errorf("pop")) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(nil, nil, false, fmt.Errorf("pop")) bm.Close() - _, _ = bm.(*batchManager).assembleMessageData(&fftypes.Message{ - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - }, - Data: fftypes.DataRefs{ - {ID: fftypes.NewUUID(), Hash: fftypes.NewRandB32()}, - }, - }) + _, _, err := bm.(*batchManager).assembleMessageData(fftypes.NewUUID()) + assert.Regexp(t, "FF10158", err) mdm.AssertExpectations(t) } @@ -574,15 +567,8 @@ func TestGetMessageNotFound(t *testing.T) { mni := &sysmessagingmocks.LocalNodeInfo{} txHelper := txcommon.NewTransactionHelper(mdi, mdm) bm, _ := NewBatchManager(context.Background(), mni, mdi, mdm, txHelper) - mdm.On("GetMessageDataCached", mock.Anything, mock.Anything).Return(nil, false, nil) + mdm.On("GetMessageWithDataCached", mock.Anything, mock.Anything).Return(nil, nil, false, nil) bm.Close() - _, err := bm.(*batchManager).assembleMessageData(&fftypes.Message{ - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - }, - Data: fftypes.DataRefs{ - {ID: fftypes.NewUUID(), Hash: fftypes.NewRandB32()}, - }, - }) + _, _, err := bm.(*batchManager).assembleMessageData(fftypes.NewUUID()) assert.Regexp(t, "FF10133", err) } diff --git a/internal/data/data_manager.go b/internal/data/data_manager.go index 991fe9dca1..6b0f52f137 100644 --- a/internal/data/data_manager.go +++ b/internal/data/data_manager.go @@ -229,7 +229,7 @@ func (dm *dataManager) queryMessageCache(ctx context.Context, id *fftypes.UUID, case CRORequirePublicBlobRefs: for idx, d := range mce.data { if d.Blob != nil && d.Blob.Public == "" { - log.L(ctx).Debugf("Cache miss for message %s - data %d (%s) is missing public blob ref", idx, d.ID, mce.msg.Header.ID) + log.L(ctx).Debugf("Cache miss for message %s - data %d (%s) is missing public blob ref", mce.msg.Header.ID, idx, d.ID) return nil } } diff --git a/internal/database/sqlcommon/message_sql.go b/internal/database/sqlcommon/message_sql.go index aa3d180348..1b31bdfa32 100644 --- a/internal/database/sqlcommon/message_sql.go +++ b/internal/database/sqlcommon/message_sql.go @@ -470,6 +470,34 @@ func (s *SQLCommon) getMessagesQuery(ctx context.Context, query sq.SelectBuilder return msgs, s.queryRes(ctx, tx, "messages", fop, fi), err } +func (s *SQLCommon) GetMessageIDs(ctx context.Context, filter database.Filter) (ids []*fftypes.IDAndSequence, err error) { + query, _, _, err := s.filterSelect(ctx, "", sq.Select("id", sequenceColumn).From("messages"), filter, msgFilterFieldMap, + []interface{}{ + &database.SortField{Field: "confirmed", Descending: true, Nulls: database.NullsFirst}, + "created", + }) + if err != nil { + return nil, err + } + + rows, _, err := s.query(ctx, query) + if err != nil { + return nil, err + } + defer rows.Close() + + ids = []*fftypes.IDAndSequence{} + for rows.Next() { + var id fftypes.IDAndSequence + err = rows.Scan(&id.ID, &id.Sequence) + if err != nil { + return nil, i18n.WrapError(ctx, err, i18n.MsgDBReadErr, "messages") + } + ids = append(ids, &id) + } + return ids, nil +} + func (s *SQLCommon) GetMessages(ctx context.Context, filter database.Filter) (message []*fftypes.Message, fr *database.FilterResult, err error) { cols := append([]string{}, msgColumns...) cols = append(cols, sequenceColumn) diff --git a/internal/database/sqlcommon/message_sql_test.go b/internal/database/sqlcommon/message_sql_test.go index 133f3f67e0..6b4d223e09 100644 --- a/internal/database/sqlcommon/message_sql_test.go +++ b/internal/database/sqlcommon/message_sql_test.go @@ -159,6 +159,12 @@ func TestUpsertE2EWithDB(t *testing.T) { msgReadJson, _ = json.Marshal(msgs[0]) assert.Equal(t, string(msgJson), string(msgReadJson)) + msgIDs, err := s.GetMessageIDs(ctx, filter) + assert.NoError(t, err) + assert.Equal(t, 1, len(msgIDs)) + assert.Equal(t, msg.Header.ID, &msgIDs[0].ID) + assert.Equal(t, msg.Sequence, msgIDs[0].Sequence) + // Check we can get it with a filter on only mesasges with a particular data ref msgs, _, err = s.GetMessagesForData(ctx, dataID2, filter.Count(true)) assert.Regexp(t, "FF10267", err) // The left join means it will take non-trivial extra work to support this. So not supported for now @@ -585,6 +591,32 @@ func TestMessageUpdateBeginFail(t *testing.T) { assert.Regexp(t, "FF10114", err) } +func TestGetMessageIDsQueryFail(t *testing.T) { + s, mock := newMockProvider().init() + mock.ExpectQuery("SELECT .*").WillReturnError(fmt.Errorf("pop")) + f := database.MessageQueryFactory.NewFilter(context.Background()).Eq("id", "") + _, err := s.GetMessageIDs(context.Background(), f) + assert.Regexp(t, "FF10115", err) + assert.NoError(t, mock.ExpectationsWereMet()) +} + +func TestGetMessageIDsReadMessageFail(t *testing.T) { + s, mock := newMockProvider().init() + mock.ExpectQuery("SELECT .*").WillReturnRows(sqlmock.NewRows([]string{"id"}).AddRow("bad id")) + f := database.MessageQueryFactory.NewFilter(context.Background()).Eq("id", "") + _, err := s.GetMessageIDs(context.Background(), f) + assert.Regexp(t, "FF10121", err) + assert.NoError(t, mock.ExpectationsWereMet()) +} + +func TestGetMessageIDsBadQuery(t *testing.T) { + s, mock := newMockProvider().init() + f := database.MessageQueryFactory.NewFilter(context.Background()).Eq("!wrong", "") + _, err := s.GetMessageIDs(context.Background(), f) + assert.Regexp(t, "FF10148", err) + assert.NoError(t, mock.ExpectationsWereMet()) +} + func TestMessageUpdateBuildQueryFail(t *testing.T) { s, mock := newMockProvider().init() mock.ExpectBegin() diff --git a/mocks/databasemocks/plugin.go b/mocks/databasemocks/plugin.go index e15b3dc4e7..896d8feda5 100644 --- a/mocks/databasemocks/plugin.go +++ b/mocks/databasemocks/plugin.go @@ -1193,6 +1193,29 @@ func (_m *Plugin) GetMessageByID(ctx context.Context, id *fftypes.UUID) (*fftype return r0, r1 } +// GetMessageIDs provides a mock function with given fields: ctx, filter +func (_m *Plugin) GetMessageIDs(ctx context.Context, filter database.Filter) ([]*fftypes.IDAndSequence, error) { + ret := _m.Called(ctx, filter) + + var r0 []*fftypes.IDAndSequence + if rf, ok := ret.Get(0).(func(context.Context, database.Filter) []*fftypes.IDAndSequence); ok { + r0 = rf(ctx, filter) + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).([]*fftypes.IDAndSequence) + } + } + + var r1 error + if rf, ok := ret.Get(1).(func(context.Context, database.Filter) error); ok { + r1 = rf(ctx, filter) + } else { + r1 = ret.Error(1) + } + + return r0, r1 +} + // GetMessages provides a mock function with given fields: ctx, filter func (_m *Plugin) GetMessages(ctx context.Context, filter database.Filter) ([]*fftypes.Message, *database.FilterResult, error) { ret := _m.Called(ctx, filter) diff --git a/pkg/database/plugin.go b/pkg/database/plugin.go index c19d3ef63d..7a4f7ddbfb 100644 --- a/pkg/database/plugin.go +++ b/pkg/database/plugin.go @@ -96,6 +96,9 @@ type iMessageCollection interface { // GetMessages - List messages, reverse sorted (newest first) by Confirmed then Created, with pagination, and simple must filters GetMessages(ctx context.Context, filter Filter) (message []*fftypes.Message, res *FilterResult, err error) + // GetMessageIDs - Retrieves messages, but only querying the messages ID (no other fields) + GetMessageIDs(ctx context.Context, filter Filter) (ids []*fftypes.IDAndSequence, err error) + // GetMessagesForData - List messages where there is a data reference to the specified ID GetMessagesForData(ctx context.Context, dataID *fftypes.UUID, filter Filter) (message []*fftypes.Message, res *FilterResult, err error) } diff --git a/pkg/fftypes/id_and_sequence.go b/pkg/fftypes/id_and_sequence.go new file mode 100644 index 0000000000..f6ceb589ff --- /dev/null +++ b/pkg/fftypes/id_and_sequence.go @@ -0,0 +1,23 @@ +// Copyright © 2022 Kaleido, Inc. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package fftypes + +// IDAndSequence is a combination of a UUID and a stored sequence +type IDAndSequence struct { + ID UUID + Sequence int64 +} From 33c244c8313fe4425ce0a02400368fef298860be Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 10:27:01 -0400 Subject: [PATCH 06/17] Prevent new msg cache overwritting batch cache of message Signed-off-by: Peter Broadhurst --- internal/data/data_manager.go | 11 ++++++++++- internal/data/data_manager_test.go | 12 ++++++++++++ internal/data/message_writer.go | 3 --- 3 files changed, 22 insertions(+), 4 deletions(-) diff --git a/internal/data/data_manager.go b/internal/data/data_manager.go index 6b0f52f137..e9a1219ae9 100644 --- a/internal/data/data_manager.go +++ b/internal/data/data_manager.go @@ -506,11 +506,20 @@ func (dm *dataManager) HydrateBatch(ctx context.Context, persistedBatch *fftypes // DB RunAsGroup - because if a large number of routines enter the same function they could starve the background // worker of the spare connection required to execute (and thus deadlock). func (dm *dataManager) WriteNewMessage(ctx context.Context, newMsg *NewMessage) error { + + if newMsg.Message == nil { + return i18n.NewError(ctx, i18n.MsgNilOrNullObject) + } + + // We add the message to the cache before we write it, because the batch aggregator might + // pick up our message from the message-writer before we return. The batch processor + // writes a more authoritative cache entry, with pings/batchID etc. + dm.UpdateMessageCache(&newMsg.Message.Message, newMsg.AllData) + err := dm.messageWriter.WriteNewMessage(ctx, newMsg) if err != nil { return err } - dm.UpdateMessageCache(&newMsg.Message.Message, newMsg.AllData) return nil } diff --git a/internal/data/data_manager_test.go b/internal/data/data_manager_test.go index 8be4529e84..7122bf531b 100644 --- a/internal/data/data_manager_test.go +++ b/internal/data/data_manager_test.go @@ -1135,3 +1135,15 @@ func TestWriteNewMessageFailNil(t *testing.T) { err := dm.WriteNewMessage(ctx, &NewMessage{}) assert.Regexp(t, "FF10368", err) } + +func TestWriteNewMessageFailClosed(t *testing.T) { + + dm, ctx, cancel := newTestDataManager(t) + defer cancel() + dm.messageWriter.close() + + err := dm.WriteNewMessage(ctx, &NewMessage{ + Message: &fftypes.MessageInOut{}, + }) + assert.Regexp(t, "FF10158", err) +} diff --git a/internal/data/message_writer.go b/internal/data/message_writer.go index 7bcfef51f4..3c0c2cc8fc 100644 --- a/internal/data/message_writer.go +++ b/internal/data/message_writer.go @@ -90,9 +90,6 @@ func newMessageWriter(ctx context.Context, di database.Plugin, conf *messageWrit func (mw *messageWriter) WriteNewMessage(ctx context.Context, newMsg *NewMessage) error { if mw.conf.workerCount > 0 { // Dispatch to background worker - if newMsg.Message == nil { - return i18n.NewError(ctx, i18n.MsgNilOrNullObject) - } nmi := &writeRequest{ newMessage: &newMsg.Message.Message, newData: newMsg.NewData, From a0232b72fada999a2b0a90b9e0386b71402b2838 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 10:46:40 -0400 Subject: [PATCH 07/17] Add debug for mismatched nextpin Signed-off-by: Peter Broadhurst --- internal/events/aggregator_batch_state.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/internal/events/aggregator_batch_state.go b/internal/events/aggregator_batch_state.go index 00820b2e67..3153b5d993 100644 --- a/internal/events/aggregator_batch_state.go +++ b/internal/events/aggregator_batch_state.go @@ -26,6 +26,7 @@ import ( "github.com/hyperledger/firefly/internal/log" "github.com/hyperledger/firefly/pkg/database" "github.com/hyperledger/firefly/pkg/fftypes" + "github.com/sirupsen/logrus" ) func newBatchState(ag *aggregator) *batchState { @@ -197,7 +198,7 @@ func (bs *batchState) CheckMaskedContextReady(ctx context.Context, msg *fftypes. } // This message must be the next hash for the author - l.Debugf("Group=%s Topic='%s' Sequence=%d Pin=%s NextPins=%v", msg.Header.Group, topic, firstMsgPinSequence, pin, npg.nextPins) + l.Debugf("Group=%s Topic='%s' Sequence=%d Pin=%s", msg.Header.Group, topic, firstMsgPinSequence, pin) var nextPin *fftypes.NextPin for _, np := range npg.nextPins { if *np.Hash == *pin { @@ -206,6 +207,11 @@ func (bs *batchState) CheckMaskedContextReady(ctx context.Context, msg *fftypes. } } if nextPin == nil || nextPin.Identity != msg.Header.Author { + if logrus.IsLevelEnabled(logrus.DebugLevel) { + for _, np := range npg.nextPins { + l.Debugf("NextPin: context=%s author=%s nonce=%d hash=%s", np.Context, np.Identity, np.Nonce, np.Hash) + } + } l.Warnf("Mismatched nexthash or author group=%s topic=%s context=%s pin=%s nextHash=%+v author=%s", msg.Header.Group, topic, contextUnmasked, pin, nextPin, msg.Header.Author) return nil, nil } From 8d6be5560db75b12cd1e11fc569d831a68a65079 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 11:06:21 -0400 Subject: [PATCH 08/17] Duplicate detection relies on accurate sequence Signed-off-by: Peter Broadhurst --- internal/batch/batch_manager.go | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/internal/batch/batch_manager.go b/internal/batch/batch_manager.go index 2330623f24..52478f2110 100644 --- a/internal/batch/batch_manager.go +++ b/internal/batch/batch_manager.go @@ -227,21 +227,25 @@ func (bm *batchManager) messageSequencer() { bm.reapQuiescing() // Read messages from the DB - in an error condition we retry until success, or a closed context - msgIDs, err := bm.readPage() + entries, err := bm.readPage() if err != nil { l.Debugf("Exiting: %s", err) return } - batchWasFull := (uint64(len(msgIDs)) == bm.readPageSize) + batchWasFull := (uint64(len(entries)) == bm.readPageSize) - if len(msgIDs) > 0 { - for _, id := range msgIDs { - msg, data, err := bm.assembleMessageData(&id.ID) + if len(entries) > 0 { + for _, entry := range entries { + msg, data, err := bm.assembleMessageData(&entry.ID) if err != nil { - l.Errorf("Failed to retrieve message data for %s: %s", id.ID, err) + l.Errorf("Failed to retrieve message data for %s (seq=%d): %s", entry.ID, entry.Sequence, err) continue } + // We likely retrieved this message from the cache, which is written by the message-writer before + // the database store. Meaning we cannot rely on the sequence having been set. + msg.Sequence = entry.Sequence + processor, err := bm.getProcessor(msg.Header.TxType, msg.Header.Type, msg.Header.Group, msg.Header.Namespace, &msg.Header.SignerRef) if err != nil { l.Errorf("Failed to dispatch message %s: %s", msg.Header.ID, err) @@ -252,7 +256,7 @@ func (bm *batchManager) messageSequencer() { } // Next time round only read after the messages we just processed (unless we get a tap to rewind) - bm.readOffset = msgIDs[len(msgIDs)-1].Sequence + bm.readOffset = entries[len(entries)-1].Sequence } // Wait to be woken again @@ -311,7 +315,7 @@ func (bm *batchManager) waitForNewMessages() (done bool) { func (bm *batchManager) dispatchMessage(processor *batchProcessor, msg *fftypes.Message, data fftypes.DataArray) { l := log.L(bm.ctx) - l.Debugf("Dispatching message %s to %s batch processor %s", msg.Header.ID, msg.Header.Type, processor.conf.name) + l.Debugf("Dispatching message %s (seq=%d) to %s batch processor %s", msg.Header.ID, msg.Sequence, msg.Header.Type, processor.conf.name) work := &batchWork{ msg: msg, data: data, From 8f63fc9185604773c6d973078f2b4c16e64d47eb Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 11:27:12 -0400 Subject: [PATCH 09/17] Prevent thrashing on new messages Signed-off-by: Peter Broadhurst --- ff-perf.log | 1 + internal/batch/batch_manager.go | 11 ++++++----- internal/batch/batch_manager_test.go | 15 +++++++++------ internal/batch/batch_processor.go | 2 +- internal/config/config.go | 3 +++ 5 files changed, 20 insertions(+), 12 deletions(-) create mode 100644 ff-perf.log diff --git a/ff-perf.log b/ff-perf.log new file mode 100644 index 0000000000..143a6bcc90 --- /dev/null +++ b/ff-perf.log @@ -0,0 +1 @@ +nohup: ff-perf: No such file or directory diff --git a/internal/batch/batch_manager.go b/internal/batch/batch_manager.go index 52478f2110..005bcc40fd 100644 --- a/internal/batch/batch_manager.go +++ b/internal/batch/batch_manager.go @@ -49,6 +49,7 @@ func NewBatchManager(ctx context.Context, ni sysmessaging.LocalNodeInfo, di data readOffset: -1, // On restart we trawl for all ready messages readPageSize: uint64(readPageSize), messagePollTimeout: config.GetDuration(config.BatchManagerReadPollTimeout), + minimumPollTime: config.GetDuration(config.BatchManagerMinimumPollTime), startupOffsetRetryAttempts: config.GetInt(config.OrchestratorStartupAttempts), dispatcherMap: make(map[string]*dispatcher), allDispatchers: make([]*dispatcher, 0), @@ -98,6 +99,7 @@ type batchManager struct { readOffset int64 readPageSize uint64 messagePollTimeout time.Duration + minimumPollTime time.Duration startupOffsetRetryAttempts int } @@ -282,17 +284,16 @@ func (bm *batchManager) newMessageNotification(seq int64) { func (bm *batchManager) drainNewMessages() bool { // Drain any new message notifications, moving back our readOffset as required newMessages := false - checkingMessages := true - for checkingMessages { + minimumPollDelay := time.NewTimer(bm.minimumPollTime) + for { select { case seq := <-bm.newMessages: bm.newMessageNotification(seq) newMessages = true - default: - checkingMessages = false + case <-minimumPollDelay.C: + return newMessages } } - return newMessages } func (bm *batchManager) waitForNewMessages() (done bool) { diff --git a/internal/batch/batch_manager_test.go b/internal/batch/batch_manager_test.go index 95a99e2e3f..81ed19ffe4 100644 --- a/internal/batch/batch_manager_test.go +++ b/internal/batch/batch_manager_test.go @@ -34,9 +34,14 @@ import ( "github.com/stretchr/testify/mock" ) -func TestE2EDispatchBroadcast(t *testing.T) { - log.SetLevel("debug") +func testConfigReset() { config.Reset() + config.Set(config.BatchManagerMinimumPollTime, "1ns") + log.SetLevel("debug") +} + +func TestE2EDispatchBroadcast(t *testing.T) { + testConfigReset() mdi := &databasemocks.Plugin{} mdm := &datamocks.Manager{} @@ -150,8 +155,7 @@ func TestE2EDispatchBroadcast(t *testing.T) { } func TestE2EDispatchPrivateUnpinned(t *testing.T) { - log.SetLevel("debug") - config.Reset() + testConfigReset() mdi := &databasemocks.Plugin{} mdm := &datamocks.Manager{} @@ -264,8 +268,7 @@ func TestE2EDispatchPrivateUnpinned(t *testing.T) { } func TestDispatchUnknownType(t *testing.T) { - log.SetLevel("debug") - config.Reset() + testConfigReset() mdi := &databasemocks.Plugin{} mdm := &datamocks.Manager{} diff --git a/internal/batch/batch_processor.go b/internal/batch/batch_processor.go index 9e521a001e..86d43c11fe 100644 --- a/internal/batch/batch_processor.go +++ b/internal/batch/batch_processor.go @@ -197,7 +197,7 @@ func (bp *batchProcessor) addWork(newWork *batchWork) (full, overflow bool) { func (bp *batchProcessor) addFlushedSequences(flushAssembly []*batchWork) { // We need to keep track of the sequences we're flushing, because until we finish our flush - // the batch processor might be re-queuing the same messages to use due to rewinds. + // the batch processor might be re-queuing the same messages to us due to rewinds. // We keep twice the batch size, which might be made up of multiple batches maxFlushedSeqLen := int(2 * bp.conf.BatchMaxSize) diff --git a/internal/config/config.go b/internal/config/config.go index f6b7bb9a0a..6df3367385 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -58,6 +58,8 @@ var ( BatchManagerReadPageSize = rootKey("batch.manager.readPageSize") // BatchManagerReadPollTimeout is how long without any notifications of new messages to wait, before doing a page query BatchManagerReadPollTimeout = rootKey("batch.manager.pollTimeout") + // BatchManagerMinimumPollTime is the minimum duration between polls, to avoid continual polling at high throughput + BatchManagerMinimumPollTime = rootKey("batch.manager.minimumPollTime") // BatchRetryFactor is the retry backoff factor for database operations performed by the batch manager BatchRetryFactor = rootKey("batch.retry.factor") // BatchRetryInitDelay is the retry initial delay for database operations @@ -305,6 +307,7 @@ func Reset() { viper.SetDefault(string(AssetManagerKeyNormalization), "blockchain_plugin") viper.SetDefault(string(BatchManagerReadPageSize), 100) viper.SetDefault(string(BatchManagerReadPollTimeout), "30s") + viper.SetDefault(string(BatchManagerMinimumPollTime), "50ms") viper.SetDefault(string(BatchRetryFactor), 2.0) viper.SetDefault(string(BatchRetryFactor), 2.0) viper.SetDefault(string(BatchRetryInitDelay), "250ms") From 21789a0a207f7772033cdd43fcf5bc515cb395f9 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 13:09:58 -0400 Subject: [PATCH 10/17] Add a prefix to the root logger, to avoid regexp extraction Signed-off-by: Peter Broadhurst --- cmd/firefly.go | 3 ++- internal/batch/batch_manager.go | 8 +++++--- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/cmd/firefly.go b/cmd/firefly.go index 59391a31e6..73a9c1e408 100644 --- a/cmd/firefly.go +++ b/cmd/firefly.go @@ -1,4 +1,4 @@ -// Copyright © 2021 Kaleido, Inc. +// Copyright © 2022 Kaleido, Inc. // // SPDX-License-Identifier: Apache-2.0 // @@ -96,6 +96,7 @@ func run() error { // Setup logging after reading config (even if failed), to output header correctly ctx, cancelCtx := context.WithCancel(context.Background()) ctx = log.WithLogger(ctx, logrus.WithField("pid", os.Getpid())) + ctx = log.WithLogger(ctx, logrus.WithField("prefix", config.GetString(config.NodeName))) config.SetupLogging(ctx) log.L(ctx).Infof("Project Firefly") diff --git a/internal/batch/batch_manager.go b/internal/batch/batch_manager.go index 005bcc40fd..9db09fb7bd 100644 --- a/internal/batch/batch_manager.go +++ b/internal/batch/batch_manager.go @@ -225,6 +225,9 @@ func (bm *batchManager) messageSequencer() { defer close(bm.done) for { + // Set a timer for the minimum time to wait before the next poll + minimumPollDelay := time.NewTimer(bm.minimumPollTime) + // Each time round the loop we check for quiescing processors bm.reapQuiescing() @@ -262,7 +265,7 @@ func (bm *batchManager) messageSequencer() { } // Wait to be woken again - if !batchWasFull && !bm.drainNewMessages() { + if !batchWasFull && !bm.drainNewMessages(minimumPollDelay) { if done := bm.waitForNewMessages(); done { l.Debugf("Exiting: %s", err) return @@ -281,10 +284,9 @@ func (bm *batchManager) newMessageNotification(seq int64) { } } -func (bm *batchManager) drainNewMessages() bool { +func (bm *batchManager) drainNewMessages(minimumPollDelay *time.Timer) bool { // Drain any new message notifications, moving back our readOffset as required newMessages := false - minimumPollDelay := time.NewTimer(bm.minimumPollTime) for { select { case seq := <-bm.newMessages: From ff877bd614854cf7624b8c602983429d48b30d29 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 13:47:28 -0400 Subject: [PATCH 11/17] Maintain a map of nodes by org Signed-off-by: Peter Broadhurst --- cmd/firefly.go | 2 +- internal/privatemessaging/privatemessaging.go | 2 ++ internal/privatemessaging/recipients.go | 31 ++++++++++++------- 3 files changed, 23 insertions(+), 12 deletions(-) diff --git a/cmd/firefly.go b/cmd/firefly.go index 73a9c1e408..0f5ec9baa1 100644 --- a/cmd/firefly.go +++ b/cmd/firefly.go @@ -95,7 +95,7 @@ func run() error { // Setup logging after reading config (even if failed), to output header correctly ctx, cancelCtx := context.WithCancel(context.Background()) - ctx = log.WithLogger(ctx, logrus.WithField("pid", os.Getpid())) + ctx = log.WithLogger(ctx, logrus.WithField("pid", fmt.Sprintf("%d", os.Getpid()))) ctx = log.WithLogger(ctx, logrus.WithField("prefix", config.GetString(config.NodeName))) config.SetupLogging(ctx) diff --git a/internal/privatemessaging/privatemessaging.go b/internal/privatemessaging/privatemessaging.go index 0bb2c05f3f..a67e1ab019 100644 --- a/internal/privatemessaging/privatemessaging.go +++ b/internal/privatemessaging/privatemessaging.go @@ -74,6 +74,7 @@ type privateMessaging struct { maxBatchPayloadLength int64 metrics metrics.Manager operations operations.Manager + orgFirstNodes map[fftypes.UUID]*fftypes.Identity } func NewPrivateMessaging(ctx context.Context, di database.Plugin, im identity.Manager, dx dataexchange.Plugin, bi blockchain.Plugin, ba batch.Manager, dm data.Manager, sa syncasync.Bridge, bp batchpin.Submitter, mm metrics.Manager, om operations.Manager) (Manager, error) { @@ -106,6 +107,7 @@ func NewPrivateMessaging(ctx context.Context, di database.Plugin, im identity.Ma maxBatchPayloadLength: config.GetByteSize(config.PrivateMessagingBatchPayloadLimit), metrics: mm, operations: om, + orgFirstNodes: make(map[fftypes.UUID]*fftypes.Identity), } pm.groupManager.groupCache = ccache.New( // We use a LRU cache with a size-aware max diff --git a/internal/privatemessaging/recipients.go b/internal/privatemessaging/recipients.go index ff693ec621..90606863cc 100644 --- a/internal/privatemessaging/recipients.go +++ b/internal/privatemessaging/recipients.go @@ -56,6 +56,24 @@ func (pm *privateMessaging) resolveRecipientList(ctx context.Context, in *fftype return err } +func (pm *privateMessaging) getFirstNodeForOrg(ctx context.Context, identity *fftypes.Identity) (*fftypes.Identity, error) { + node := pm.orgFirstNodes[*identity.ID] + if node == nil && identity.Type == fftypes.IdentityTypeOrg { + fb := database.IdentityQueryFactory.NewFilterLimit(ctx, 1) + filter := fb.And( + fb.Eq("parent", identity.ID), + fb.Eq("type", fftypes.IdentityTypeNode), + ) + nodes, _, err := pm.database.GetIdentities(ctx, filter) + if err != nil || len(nodes) == 0 { + return nil, err + } + node = nodes[0] + pm.orgFirstNodes[*identity.ID] = node + } + return node, nil +} + func (pm *privateMessaging) resolveNode(ctx context.Context, identity *fftypes.Identity, nodeInput string) (node *fftypes.Identity, err error) { retryable := true if nodeInput != "" { @@ -64,19 +82,10 @@ func (pm *privateMessaging) resolveNode(ctx context.Context, identity *fftypes.I // Find any node owned by this organization inputIdentityDebugInfo := fmt.Sprintf("%s (%s)", identity.DID, identity.ID) for identity != nil && node == nil { - var nodes []*fftypes.Identity - if identity.Type == fftypes.IdentityTypeOrg { - fb := database.IdentityQueryFactory.NewFilterLimit(ctx, 1) - filter := fb.And( - fb.Eq("parent", identity.ID), - fb.Eq("type", fftypes.IdentityTypeNode), - ) - nodes, _, err = pm.database.GetIdentities(ctx, filter) - } + node, err = pm.getFirstNodeForOrg(ctx, identity) switch { - case err == nil && len(nodes) > 0: + case err == nil && node != nil: // This is an org, and it owns a node - node = nodes[0] case err == nil && identity.Parent != nil: // This identity has a parent, maybe that org owns a node identity, err = pm.identity.CachedIdentityLookupByID(ctx, identity.Parent) From d1dea98dfdf0aa5f4ea7cfa5be7737d3ea389888 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 16:28:03 -0400 Subject: [PATCH 12/17] Optimize batch message/data insertion Signed-off-by: Peter Broadhurst --- internal/data/data_manager.go | 9 + internal/data/data_manager_test.go | 6 + internal/database/sqlcommon/data_sql.go | 2 +- internal/database/sqlcommon/message_sql.go | 2 +- internal/events/batch_pin_complete_test.go | 321 +++++---------------- internal/events/dx_callbacks_test.go | 64 ++-- internal/events/persist_batch.go | 218 +++++++++----- internal/events/persist_batch_test.go | 213 ++++++++++---- internal/i18n/en_translations.go | 2 +- mocks/datamocks/manager.go | 32 ++ pkg/fftypes/batch.go | 2 +- 11 files changed, 452 insertions(+), 419 deletions(-) diff --git a/internal/data/data_manager.go b/internal/data/data_manager.go index e9a1219ae9..a74ee80baa 100644 --- a/internal/data/data_manager.go +++ b/internal/data/data_manager.go @@ -37,6 +37,7 @@ type Manager interface { ValidateAll(ctx context.Context, data fftypes.DataArray) (valid bool, err error) GetMessageWithDataCached(ctx context.Context, msgID *fftypes.UUID, options ...CacheReadOption) (msg *fftypes.Message, data fftypes.DataArray, foundAllData bool, err error) GetMessageDataCached(ctx context.Context, msg *fftypes.Message, options ...CacheReadOption) (data fftypes.DataArray, foundAll bool, err error) + PeekMessageCache(ctx context.Context, id *fftypes.UUID, options ...CacheReadOption) (msg *fftypes.Message, data fftypes.DataArray) UpdateMessageCache(msg *fftypes.Message, data fftypes.DataArray) UpdateMessageIfCached(ctx context.Context, msg *fftypes.Message) ResolveInlineData(ctx context.Context, msg *NewMessage) error @@ -217,6 +218,14 @@ func (dm *dataManager) dataLookupAndCache(ctx context.Context, msg *fftypes.Mess return data, true, nil } +func (dm *dataManager) PeekMessageCache(ctx context.Context, id *fftypes.UUID, options ...CacheReadOption) (msg *fftypes.Message, data fftypes.DataArray) { + mce := dm.queryMessageCache(ctx, id, options...) + if mce != nil { + return mce.msg, mce.data + } + return nil, nil +} + func (dm *dataManager) queryMessageCache(ctx context.Context, id *fftypes.UUID, options ...CacheReadOption) *messageCacheEntry { cached := dm.messageCache.Get(id.String()) if cached == nil { diff --git a/internal/data/data_manager_test.go b/internal/data/data_manager_test.go index 7122bf531b..fedc9bd687 100644 --- a/internal/data/data_manager_test.go +++ b/internal/data/data_manager_test.go @@ -1082,8 +1082,14 @@ func TestUpdateMessageCacheCRORequirePins(t *testing.T) { Pins: fftypes.FFStringArray{"pin1"}, } + msg, _ := dm.PeekMessageCache(ctx, msgWithPins.Header.ID) + assert.Nil(t, msg) + dm.UpdateMessageCache(msgNoPins, data) + msg, _ = dm.PeekMessageCache(ctx, msgWithPins.Header.ID) + assert.NotNil(t, msg) + mce := dm.queryMessageCache(ctx, msgNoPins.Header.ID, CRORequirePins) assert.Nil(t, mce) diff --git a/internal/database/sqlcommon/data_sql.go b/internal/database/sqlcommon/data_sql.go index 352e5af3b1..1066d009c3 100644 --- a/internal/database/sqlcommon/data_sql.go +++ b/internal/database/sqlcommon/data_sql.go @@ -198,7 +198,7 @@ func (s *SQLCommon) InsertDataArray(ctx context.Context, dataArray fftypes.DataA for _, data := range dataArray { s.callbacks.UUIDCollectionNSEvent(database.CollectionData, fftypes.ChangeEventTypeCreated, data.Namespace, data.ID) } - }, sequences, false) + }, sequences, true /* we want the caller to be able to retry with individual upserts */) if err != nil { return err } diff --git a/internal/database/sqlcommon/message_sql.go b/internal/database/sqlcommon/message_sql.go index 1b31bdfa32..7bc58bfa5b 100644 --- a/internal/database/sqlcommon/message_sql.go +++ b/internal/database/sqlcommon/message_sql.go @@ -217,7 +217,7 @@ func (s *SQLCommon) InsertMessages(ctx context.Context, messages []*fftypes.Mess message.Sequence = sequences[i] s.callbacks.OrderedUUIDCollectionNSEvent(database.CollectionMessages, fftypes.ChangeEventTypeCreated, message.Header.Namespace, message.Header.ID, message.Sequence) } - }, sequences, false) + }, sequences, true /* we want the caller to be able to retry with individual upserts */) if err != nil { return err } diff --git a/internal/events/batch_pin_complete_test.go b/internal/events/batch_pin_complete_test.go index 15934090bc..f5ccd87df6 100644 --- a/internal/events/batch_pin_complete_test.go +++ b/internal/events/batch_pin_complete_test.go @@ -26,6 +26,7 @@ import ( "github.com/hyperledger/firefly/mocks/blockchainmocks" "github.com/hyperledger/firefly/mocks/databasemocks" + "github.com/hyperledger/firefly/mocks/datamocks" "github.com/hyperledger/firefly/mocks/identitymanagermocks" "github.com/hyperledger/firefly/mocks/sharedstoragemocks" "github.com/hyperledger/firefly/mocks/txcommonmocks" @@ -36,22 +37,30 @@ import ( "github.com/stretchr/testify/mock" ) -func sampleBatch(t *testing.T, txType fftypes.TransactionType, data ...*fftypes.Data) *fftypes.Batch { +func sampleBatch(t *testing.T, batchType fftypes.BatchType, txType fftypes.TransactionType, data fftypes.DataArray) *fftypes.Batch { identity := fftypes.SignerRef{Author: "signingOrg", Key: "0x12345"} + msgType := fftypes.MessageTypeBroadcast + if batchType == fftypes.BatchTypePrivate { + msgType = fftypes.MessageTypePrivate + } + for _, d := range data { + err := d.Seal(context.Background(), nil) + assert.NoError(t, err) + } msg := &fftypes.Message{ Header: fftypes.MessageHeader{ SignerRef: identity, ID: fftypes.NewUUID(), + Type: msgType, TxType: txType, + Topics: fftypes.FFStringArray{"topic1"}, }, - } - for _, d := range data { - err := d.Seal(context.Background(), nil) - assert.NoError(t, err) + Data: data.Refs(), } batch := &fftypes.Batch{ BatchHeader: fftypes.BatchHeader{ SignerRef: identity, + Type: batchType, ID: fftypes.NewUUID(), Node: fftypes.NewUUID(), }, @@ -69,14 +78,17 @@ func sampleBatch(t *testing.T, txType fftypes.TransactionType, data ...*fftypes. batch.Hash = batch.Payload.Hash() return batch } + func TestBatchPinCompleteOkBroadcast(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := &blockchain.BatchPin{ + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batchPin := &blockchain.BatchPin{ Namespace: "ns1", - TransactionID: fftypes.NewUUID(), - BatchID: fftypes.NewUUID(), + TransactionID: batch.Payload.TX.ID, + BatchID: batch.ID, BatchPayloadRef: "Qmf412jQZiuVUtdgnB36FXFX7xg5V6KEbSJ4dpQuhkLyfD", Contexts: []*fftypes.Bytes32{fftypes.NewRandB32()}, Event: blockchain.Event{ @@ -85,40 +97,22 @@ func TestBatchPinCompleteOkBroadcast(t *testing.T) { ProtocolID: "10/20/30", }, } - batchData := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: batch.BatchID, - Namespace: "ns1", - SignerRef: fftypes.SignerRef{ - Author: "author1", - Key: "0x22222", - }, - }, - PayloadRef: batch.BatchPayloadRef, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: batch.TransactionID, - }, - Messages: []*fftypes.Message{}, - Data: fftypes.DataArray{}, - }, - } - batchData.Hash = batchData.Payload.Hash() - batch.BatchHash = batchData.Hash - batchDataBytes, err := json.Marshal(&batchData) + + batch.Hash = batch.Payload.Hash() + batchPin.BatchHash = batch.Hash + batchDataBytes, err := json.Marshal(&batch) assert.NoError(t, err) batchReadCloser := ioutil.NopCloser(bytes.NewReader(batchDataBytes)) mpi := em.sharedstorage.(*sharedstoragemocks.Plugin) mpi.On("RetrieveData", mock.Anything, mock. - MatchedBy(func(pr string) bool { return pr == batch.BatchPayloadRef })). + MatchedBy(func(pr string) bool { return pr == batchPin.BatchPayloadRef })). Return(batchReadCloser, nil) mth := em.txHelper.(*txcommonmocks.Helper) - mth.On("PersistTransaction", mock.Anything, "ns1", batch.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345"). + mth.On("PersistTransaction", mock.Anything, "ns1", batchPin.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345"). Return(false, fmt.Errorf("pop")).Once() - mth.On("PersistTransaction", mock.Anything, "ns1", batch.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345"). + mth.On("PersistTransaction", mock.Anything, "ns1", batchPin.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345"). Return(true, nil) mdi := em.database.(*databasemocks.Plugin) @@ -132,35 +126,40 @@ func TestBatchPinCompleteOkBroadcast(t *testing.T) { } mdi.On("InsertBlockchainEvent", mock.Anything, mock.MatchedBy(func(e *fftypes.BlockchainEvent) bool { - return e.Name == batch.Event.Name + return e.Name == batchPin.Event.Name })).Return(fmt.Errorf("pop")).Once() mdi.On("InsertBlockchainEvent", mock.Anything, mock.MatchedBy(func(e *fftypes.BlockchainEvent) bool { - return e.Name == batch.Event.Name + return e.Name == batchPin.Event.Name })).Return(nil).Times(2) mdi.On("InsertEvent", mock.Anything, mock.MatchedBy(func(e *fftypes.Event) bool { return e.Type == fftypes.EventTypeBlockchainEventReceived })).Return(nil).Times(2) mdi.On("InsertPins", mock.Anything, mock.Anything).Return(nil).Once() mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(nil).Once() + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(nil).Once() + mdi.On("InsertMessages", mock.Anything, mock.Anything).Return(nil).Once() mbi := &blockchainmocks.Plugin{} - mim := em.identity.(*identitymanagermocks.Manager) - mim.On("NormalizeSigningKeyIdentity", mock.Anything, "0x12345").Return("author1", nil) + mdm := em.data.(*datamocks.Manager) + mdm.On("UpdateMessageCache", mock.Anything, mock.Anything).Return() - err = em.BatchPinComplete(mbi, batch, &fftypes.VerifierRef{ + err = em.BatchPinComplete(mbi, batchPin, &fftypes.VerifierRef{ Type: fftypes.VerifierTypeEthAddress, Value: "0x12345", }) assert.NoError(t, err) mdi.AssertExpectations(t) + mpi.AssertExpectations(t) + mth.AssertExpectations(t) + mdm.AssertExpectations(t) } func TestBatchPinCompleteOkPrivate(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := &blockchain.BatchPin{ + batchPin := &blockchain.BatchPin{ Namespace: "ns1", TransactionID: fftypes.NewUUID(), BatchID: fftypes.NewUUID(), @@ -169,32 +168,9 @@ func TestBatchPinCompleteOkPrivate(t *testing.T) { BlockchainTXID: "0x12345", }, } - batchData := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: batch.BatchID, - Namespace: "ns1", - }, - PayloadRef: batch.BatchPayloadRef, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: batch.TransactionID, - }, - Messages: []*fftypes.Message{}, - Data: fftypes.DataArray{}, - }, - } - batchDataBytes, err := json.Marshal(&batchData) - assert.NoError(t, err) - batchReadCloser := ioutil.NopCloser(bytes.NewReader(batchDataBytes)) - - mpi := em.sharedstorage.(*sharedstoragemocks.Plugin) - mpi.On("RetrieveData", mock.Anything, mock. - MatchedBy(func(pr string) bool { return pr == batch.BatchPayloadRef })). - Return(batchReadCloser, nil) mth := em.txHelper.(*txcommonmocks.Helper) - mth.On("PersistTransaction", mock.Anything, "ns1", batch.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345").Return(true, nil) + mth.On("PersistTransaction", mock.Anything, "ns1", batchPin.TransactionID, fftypes.TransactionTypeBatchPin, "0x12345").Return(true, nil) mdi := em.database.(*databasemocks.Plugin) mdi.On("RunAsGroup", mock.Anything, mock.Anything).Return(nil) @@ -202,7 +178,7 @@ func TestBatchPinCompleteOkPrivate(t *testing.T) { mdi.On("UpsertPin", mock.Anything, mock.Anything).Return(nil) mbi := &blockchainmocks.Plugin{} - err = em.BatchPinComplete(mbi, batch, &fftypes.VerifierRef{ + err := em.BatchPinComplete(mbi, batchPin, &fftypes.VerifierRef{ Type: fftypes.VerifierTypeEthAddress, Value: "0xffffeeee", }) @@ -215,6 +191,7 @@ func TestBatchPinCompleteOkPrivate(t *testing.T) { assert.NoError(t, err) mdi.AssertExpectations(t) + mth.AssertExpectations(t) } func TestSequencedBroadcastRetrieveIPFSFail(t *testing.T) { @@ -397,22 +374,8 @@ func TestPersistBatchMismatchChainHash(t *testing.T) { func TestPersistBatchUpsertBatchMismatchHash(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - SignerRef: fftypes.SignerRef{ - Author: "author1", - Key: "0x12345", - }, - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: fftypes.NewUUID(), - }, - }, - } - batch.Hash = batch.Payload.Hash() + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) mdi := em.database.(*databasemocks.Plugin) mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(database.HashMismatch) @@ -425,6 +388,19 @@ func TestPersistBatchUpsertBatchMismatchHash(t *testing.T) { } func TestPersistBatchBadHash(t *testing.T) { + em, cancel := newTestEventManager(t) + defer cancel() + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Hash = fftypes.NewRandB32() + + bp, valid, err := em.persistBatch(context.Background(), batch) + assert.False(t, valid) + assert.Nil(t, bp) + assert.NoError(t, err) +} + +func TestPersistBatchNoData(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() batch := &fftypes.Batch{ @@ -453,22 +429,8 @@ func TestPersistBatchBadHash(t *testing.T) { func TestPersistBatchUpsertBatchFail(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - SignerRef: fftypes.SignerRef{ - Author: "author1", - Key: "0x12345", - }, - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: fftypes.NewUUID(), - }, - }, - } - batch.Hash = batch.Payload.Hash() + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) mdi := em.database.(*databasemocks.Plugin) mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) @@ -512,34 +474,15 @@ func TestPersistBatchSwallowBadData(t *testing.T) { mdi.AssertExpectations(t) } -func TestPersistBatchGoodDataUpsertOptimizeExistingFail(t *testing.T) { +func TestPersistBatchGoodDataUpsertOptimizFail(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - Node: testNodeID, - SignerRef: fftypes.SignerRef{ - Author: "author1", - Key: "0x12345", - }, - Namespace: "ns1", - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: fftypes.NewUUID(), - }, - Data: fftypes.DataArray{ - {ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)}, - }, - }, - } - batch.Payload.Data[0].Hash = batch.Payload.Data[0].Value.Hash() - batch.Hash = batch.Payload.Hash() + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) mdi := em.database.(*databasemocks.Plugin) mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(fmt.Errorf("optimzation miss")) mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationExisting).Return(fmt.Errorf("pop")) bp, valid, err := em.persistBatch(context.Background(), batch) @@ -548,54 +491,17 @@ func TestPersistBatchGoodDataUpsertOptimizeExistingFail(t *testing.T) { assert.EqualError(t, err, "pop") } -func TestPersistBatchGoodDataUpsertOptimizeNewFail(t *testing.T) { - em, cancel := newTestEventManager(t) - defer cancel() - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - Node: fftypes.NewUUID(), - SignerRef: fftypes.SignerRef{ - Author: "author1", - Key: "0x12345", - }, - Namespace: "ns1", - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - Type: fftypes.TransactionTypeBatchPin, - ID: fftypes.NewUUID(), - }, - Data: fftypes.DataArray{ - {ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)}, - }, - }, - } - batch.Payload.Data[0].Hash = batch.Payload.Data[0].Value.Hash() - batch.Hash = batch.Payload.Hash() - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(nil) - mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationNew).Return(fmt.Errorf("pop")) - - bp, valid, err := em.persistBatch(context.Background(), batch) - assert.Nil(t, bp) - assert.False(t, valid) - assert.EqualError(t, err, "pop") -} - func TestPersistBatchGoodDataMessageFail(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) - batch.Node = nil - batch.Payload.Messages[0].Header.DataHash = batch.Payload.Messages[0].Data.Hash() - batch.Payload.Messages[0].Hash = batch.Payload.Messages[0].Header.Hash() - batch.Hash = batch.Payload.Hash() + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) mdi := em.database.(*databasemocks.Plugin) mdi.On("UpsertBatch", mock.Anything, mock.Anything).Return(nil) - mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(fmt.Errorf("pop")) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertMessages", mock.Anything, mock.Anything).Return(fmt.Errorf("optimzation miss")) + mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationExisting).Return(fmt.Errorf("pop")) bp, valid, err := em.persistBatch(context.Background(), batch) assert.False(t, valid) @@ -606,7 +512,8 @@ func TestPersistBatchGoodDataMessageFail(t *testing.T) { func TestPersistBatchGoodMessageAuthorMismatch(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) batch.Payload.Messages[0].Header.Key = "0x9999999" batch.Payload.Messages[0].Header.DataHash = batch.Payload.Messages[0].Data.Hash() batch.Payload.Messages[0].Hash = batch.Payload.Messages[0].Header.Hash() @@ -632,8 +539,7 @@ func TestPersistBatchDataNilData(t *testing.T) { data := &fftypes.Data{ ID: fftypes.NewUUID(), } - valid, err := em.persistBatchData(context.Background(), batch, 0, data, database.UpsertOptimizationSkip) - assert.NoError(t, err) + valid := em.validateBatchData(context.Background(), batch, 0, data) assert.False(t, valid) } @@ -644,60 +550,21 @@ func TestPersistBatchDataBadHash(t *testing.T) { ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`), } - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin, data) + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) batch.Payload.Data[0].Hash = fftypes.NewRandB32() - valid, err := em.persistBatchData(context.Background(), batch, 0, data, database.UpsertOptimizationSkip) - assert.NoError(t, err) + valid := em.validateBatchData(context.Background(), batch, 0, data) assert.False(t, valid) } -func TestPersistBatchDataUpsertHashMismatch(t *testing.T) { - em, cancel := newTestEventManager(t) - defer cancel() - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) - batch.Hash = fftypes.NewRandB32() - - data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} - data.Hash = data.Value.Hash() - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(database.HashMismatch) - - valid, err := em.persistBatchData(context.Background(), batch, 0, data, database.UpsertOptimizationSkip) - assert.False(t, valid) - assert.NoError(t, err) - mdi.AssertExpectations(t) -} - -func TestPersistBatchDataUpsertDataError(t *testing.T) { - em, cancel := newTestEventManager(t) - defer cancel() - - data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin, data) - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(fmt.Errorf("pop")) - - valid, err := em.persistBatchData(context.Background(), batch, 0, data, database.UpsertOptimizationSkip) - assert.False(t, valid) - assert.EqualError(t, err, "pop") -} - func TestPersistBatchDataOk(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin, data) - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(nil) + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) - valid, err := em.persistBatchData(context.Background(), batch, 0, data, database.UpsertOptimizationSkip) + valid := em.validateBatchData(context.Background(), batch, 0, data) assert.True(t, valid) - assert.NoError(t, err) - mdi.AssertExpectations(t) } func TestPersistBatchMessageNilData(t *testing.T) { @@ -713,51 +580,17 @@ func TestPersistBatchMessageNilData(t *testing.T) { ID: fftypes.NewUUID(), }, } - valid, err := em.persistBatchMessage(context.Background(), batch, 0, msg, database.UpsertOptimizationSkip) + valid := em.validateBatchMessage(context.Background(), batch, 0, msg) assert.False(t, valid) - assert.NoError(t, err) -} - -func TestPersistBatchMessageUpsertHashMismatch(t *testing.T) { - em, cancel := newTestEventManager(t) - defer cancel() - - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(database.HashMismatch) - - valid, err := em.persistBatchMessage(context.Background(), batch, 0, batch.Payload.Messages[0], database.UpsertOptimizationSkip) - assert.False(t, valid) - assert.NoError(t, err) - mdi.AssertExpectations(t) -} - -func TestPersistBatchMessageUpsertMessageFail(t *testing.T) { - em, cancel := newTestEventManager(t) - defer cancel() - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(fmt.Errorf("pop")) - - valid, err := em.persistBatchMessage(context.Background(), batch, 0, batch.Payload.Messages[0], database.UpsertOptimizationSkip) - assert.False(t, valid) - assert.EqualError(t, err, "pop") } func TestPersistBatchMessageOK(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - batch := sampleBatch(t, fftypes.TransactionTypeBatchPin) - - mdi := em.database.(*databasemocks.Plugin) - mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationSkip).Return(nil) + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{}) - valid, err := em.persistBatchMessage(context.Background(), batch, 0, batch.Payload.Messages[0], database.UpsertOptimizationSkip) + valid := em.validateBatchMessage(context.Background(), batch, 0, batch.Payload.Messages[0]) assert.True(t, valid) - assert.NoError(t, err) - mdi.AssertExpectations(t) } func TestPersistContextsFail(t *testing.T) { diff --git a/internal/events/dx_callbacks_test.go b/internal/events/dx_callbacks_test.go index c75cefd9b9..04776a9add 100644 --- a/internal/events/dx_callbacks_test.go +++ b/internal/events/dx_callbacks_test.go @@ -35,8 +35,9 @@ import ( "github.com/stretchr/testify/mock" ) -func sampleBatchTransfer(t *testing.T, txType fftypes.TransactionType, data ...*fftypes.Data) (*fftypes.Batch, []byte) { - batch := sampleBatch(t, txType, data...) +func sampleBatchTransfer(t *testing.T, txType fftypes.TransactionType) (*fftypes.Batch, []byte) { + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypePrivate, txType, fftypes.DataArray{data}) b, _ := json.Marshal(&fftypes.TransportWrapper{ Batch: batch, Group: &fftypes.Group{ @@ -97,7 +98,8 @@ func TestPinnedReceiveOK(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil, nil) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(nil, nil) + mdi.On("InsertMessages", em.ctx, mock.Anything).Return(nil, nil) mdm := em.data.(*datamocks.Manager) mdm.On("UpdateMessageCache", mock.Anything, mock.Anything).Return() @@ -726,7 +728,9 @@ func TestMessageReceiveMessagePersistMessageFail(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(fmt.Errorf("pop")) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(nil) + mdi.On("InsertMessages", em.ctx, mock.Anything).Return(fmt.Errorf("optimization fail")) + mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationExisting).Return(fmt.Errorf("pop")) m, err := em.MessageReceived(mdx, "peer1", b) assert.Regexp(t, "FF10158", err) @@ -740,11 +744,7 @@ func TestMessageReceiveMessagePersistDataFail(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} @@ -761,7 +761,8 @@ func TestMessageReceiveMessagePersistDataFail(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertData", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(fmt.Errorf("pop")) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(fmt.Errorf("optimization miss")) + mdi.On("UpsertData", em.ctx, mock.Anything, database.UpsertOptimizationExisting).Return(fmt.Errorf("pop")) m, err := em.MessageReceived(mdx, "peer1", b) assert.Regexp(t, "FF10158", err) @@ -775,11 +776,7 @@ func TestMessageReceiveUnpinnedBatchOk(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} @@ -796,8 +793,8 @@ func TestMessageReceiveUnpinnedBatchOk(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertData", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) - mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(nil) + mdi.On("InsertMessages", em.ctx, mock.Anything).Return(nil) mdi.On("UpdateMessages", em.ctx, mock.Anything, mock.Anything).Return(nil) mdi.On("InsertEvent", em.ctx, mock.Anything).Return(nil) mdm := em.data.(*datamocks.Manager) @@ -811,15 +808,12 @@ func TestMessageReceiveUnpinnedBatchOk(t *testing.T) { mdx.AssertExpectations(t) mdm.AssertExpectations(t) } + func TestMessageReceiveUnpinnedBatchConfirmMessagesFail(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} @@ -836,8 +830,8 @@ func TestMessageReceiveUnpinnedBatchConfirmMessagesFail(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertData", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) - mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(nil) + mdi.On("InsertMessages", em.ctx, mock.Anything).Return(nil) mdi.On("UpdateMessages", em.ctx, mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) mdm := em.data.(*datamocks.Manager) mdm.On("UpdateMessageCache", mock.Anything, mock.Anything).Return() @@ -855,11 +849,7 @@ func TestMessageReceiveUnpinnedBatchPersistEventFail(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} @@ -876,8 +866,8 @@ func TestMessageReceiveUnpinnedBatchPersistEventFail(t *testing.T) { }).Return(node1, nil) mim.On("CachedIdentityLookup", em.ctx, "signingOrg").Return(org1, false, nil) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpsertData", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) - mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationNew).Return(nil) + mdi.On("InsertDataArray", em.ctx, mock.Anything).Return(nil) + mdi.On("InsertMessages", em.ctx, mock.Anything).Return(nil) mdi.On("UpdateMessages", em.ctx, mock.Anything, mock.Anything).Return(nil) mdi.On("InsertEvent", em.ctx, mock.Anything).Return(fmt.Errorf("pop")) mdm := em.data.(*datamocks.Manager) @@ -896,11 +886,7 @@ func TestMessageReceiveMessageEnsureLocalGroupFail(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} @@ -920,11 +906,7 @@ func TestMessageReceiveMessageEnsureLocalGroupReject(t *testing.T) { em, cancel := newTestEventManager(t) cancel() // to avoid infinite retry - data := &fftypes.Data{ - ID: fftypes.NewUUID(), - Value: fftypes.JSONAnyPtr(`{}`), - } - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned, data) + _, b := sampleBatchTransfer(t, fftypes.TransactionTypeUnpinned) mdi := em.database.(*databasemocks.Plugin) mdx := &dataexchangemocks.Plugin{} diff --git a/internal/events/persist_batch.go b/internal/events/persist_batch.go index c356bf4402..5a90c37c04 100644 --- a/internal/events/persist_batch.go +++ b/internal/events/persist_batch.go @@ -24,6 +24,11 @@ import ( "github.com/hyperledger/firefly/pkg/fftypes" ) +type messageAndData struct { + message *fftypes.Message + data fftypes.DataArray +} + func (em *eventManager) persistBatchFromBroadcast(ctx context.Context /* db TX context*/, batch *fftypes.Batch, onchainHash *fftypes.Bytes32) (valid bool, err error) { if !onchainHash.Equals(batch.Hash) { @@ -45,6 +50,11 @@ func (em *eventManager) persistBatch(ctx context.Context /* db TX context*/, bat return nil, false, nil // This is not retryable. skip this batch } + if len(batch.Payload.Messages) == 0 || len(batch.Payload.Data) == 0 { + l.Errorf("Invalid batch '%s'. Missing messages (%d) or data (%d)", batch.ID, len(batch.Payload.Messages), len(batch.Payload.Data)) + return nil, false, nil // This is not retryable. skip this batch + } + switch batch.Payload.TX.Type { case fftypes.TransactionTypeBatchPin: case fftypes.TransactionTypeUnpinned: @@ -80,138 +90,196 @@ func (em *eventManager) persistBatch(ctx context.Context /* db TX context*/, bat return nil, false, err // a persistence failure here is considered retryable (so returned) } - valid, err = em.persistBatchContent(ctx, batch) + valid, err = em.validateAndPersistBatchContent(ctx, batch) if err != nil || !valid { return nil, valid, err } return persistedBatch, valid, err } -func (em *eventManager) persistBatchContent(ctx context.Context, batch *fftypes.Batch) (valid bool, err error) { - - optimization := em.getOptimization(ctx, batch) +func (em *eventManager) validateAndPersistBatchContent(ctx context.Context, batch *fftypes.Batch) (valid bool, err error) { // Insert the data entries dataByID := make(map[fftypes.UUID]*fftypes.Data) for i, data := range batch.Payload.Data { - if valid, err = em.persistBatchData(ctx, batch, i, data, optimization); !valid || err != nil { - return valid, err + if valid = em.validateBatchData(ctx, batch, i, data); !valid { + return false, nil } dataByID[*data.ID] = data } // Insert the message entries for i, msg := range batch.Payload.Messages { - if valid, err = em.persistBatchMessage(ctx, batch, i, msg, optimization); !valid || err != nil { - return valid, err + if valid = em.validateBatchMessage(ctx, batch, i, msg); !valid { + return false, nil } - dataInBatch := true + } + + // We require that the batch contains exactly the set of data that is in the messages - no more or less. + // While this means an edge case inefficiencly of re-transmission of data when sent in multiple messages, + // that is outweighed by the efficiency it allows in the insertion logic in the majority case. + matchedData := make(map[fftypes.UUID]bool) + matchedMsgs := make([]*messageAndData, len(batch.Payload.Messages)) + for iMsg, msg := range batch.Payload.Messages { msgData := make(fftypes.DataArray, len(msg.Data)) for di, dataRef := range msg.Data { msgData[di] = dataByID[*dataRef.ID] if msgData[di] == nil || !msgData[di].Hash.Equals(dataRef.Hash) { - log.L(ctx).Debugf("Message '%s' in batch '%s' - data not in-line in batch id='%s' hash='%s'", msg.Header.ID, batch.ID, dataRef.ID, dataRef.Hash) - dataInBatch = false - break + log.L(ctx).Errorf("Message '%s' in batch '%s' - data not in-line in batch id='%s' hash='%s'", msg.Header.ID, batch.ID, dataRef.ID, dataRef.Hash) + return false, nil } + matchedData[*dataRef.ID] = true } - if dataInBatch { - // We can push the complete message into the cache straight away - em.data.UpdateMessageCache(msg, msgData) + matchedMsgs[iMsg] = &messageAndData{ + message: msg, + data: msgData, } } - - return true, nil -} - -func (em *eventManager) getOptimization(ctx context.Context, batch *fftypes.Batch) database.UpsertOptimization { - localNode := em.ni.GetNodeUUID(ctx) - if batch.Node == nil { - // This is from a node that hasn't yet completed registration, so we can't optimize - return database.UpsertOptimizationSkip - } else if localNode != nil && localNode.Equals(batch.Node) { - // We sent the batch, so we should already have all the messages and data locally - optimize the DB operations for that - return database.UpsertOptimizationExisting + if len(matchedData) != len(dataByID) { + log.L(ctx).Errorf("Batch '%s' contains %d unique data, but %d are referenced from messages", batch.ID, len(dataByID), len(matchedData)) + return false, nil } - // We didn't send the batch, so all the data should be new - optimize the DB operations for that - return database.UpsertOptimizationNew -} -func (em *eventManager) persistBatchData(ctx context.Context /* db TX context*/, batch *fftypes.Batch, i int, data *fftypes.Data, optimization database.UpsertOptimization) (bool, error) { - return em.persistReceivedData(ctx, i, data, "batch", batch.ID, optimization) + return em.persistBatchContent(ctx, batch, matchedMsgs) } -func (em *eventManager) persistReceivedData(ctx context.Context /* db TX context*/, i int, data *fftypes.Data, mType string, mID *fftypes.UUID, optimization database.UpsertOptimization) (bool, error) { +func (em *eventManager) validateBatchData(ctx context.Context, batch *fftypes.Batch, i int, data *fftypes.Data) bool { l := log.L(ctx) - l.Tracef("%s '%s' data %d: %+v", mType, mID, i, data) + l.Tracef("Batch '%s' data %d: %+v", batch.ID, i, data) if data == nil { - l.Errorf("null data entry %d in %s '%s'", i, mType, mID) - return false, nil // skip data entry + l.Errorf("null data entry %d in batch '%s'", i, batch.ID) + return false } hash, err := data.CalcHash(ctx) if err != nil { - log.L(ctx).Errorf("Invalid data entry %d in %s '%s': %s", i, mType, mID, err) - return false, nil // + log.L(ctx).Errorf("Invalid data entry %d in batch '%s': %s", i, batch.ID, err) + return false } if data.Hash == nil || *data.Hash != *hash { - log.L(ctx).Errorf("Invalid data entry %d in %s '%s': Hash=%v Expected=%v", i, mType, mID, data.Hash, hash) - return false, nil // skip data entry + log.L(ctx).Errorf("Invalid data entry %d in batch '%s': Hash=%v Expected=%v", i, batch.ID, data.Hash, hash) + return false } - // Insert the data, ensuring the hash doesn't change - if err := em.database.UpsertData(ctx, data, optimization); err != nil { - if err == database.HashMismatch { - log.L(ctx).Errorf("Invalid data entry %d in %s '%s'. Hash mismatch with existing record with same UUID '%s' Hash=%s", i, mType, mID, data.ID, data.Hash) - return false, nil // This is not retryable. skip this data entry - } - log.L(ctx).Errorf("Failed to insert data entry %d in %s '%s': %s", i, mType, mID, err) - return false, err // a persistence failure here is considered retryable (so returned) + return true +} + +func (em *eventManager) validateBatchMessage(ctx context.Context, batch *fftypes.Batch, i int, msg *fftypes.Message) bool { + + l := log.L(ctx) + if msg == nil { + l.Errorf("null message entry %d in batch '%s'", i, batch.ID) + return false } - return true, nil + if msg.Header.Author != batch.Author || msg.Header.Key != batch.Key { + log.L(ctx).Errorf("Mismatched key/author '%s'/'%s' on message entry %d in batch '%s'", msg.Header.Key, msg.Header.Author, i, batch.ID) + return false + } + msg.BatchID = batch.ID + + l.Tracef("Batch '%s' message %d: %+v", batch.ID, i, msg) + + err := msg.Verify(ctx) + if err != nil { + l.Errorf("Invalid message entry %d in batch '%s': %s", i, batch.ID, err) + return false + } + // Set the state to pending, for the insertion stage + msg.State = fftypes.MessageStatePending + + return true } -func (em *eventManager) persistBatchMessage(ctx context.Context /* db TX context*/, batch *fftypes.Batch, i int, msg *fftypes.Message, optimization database.UpsertOptimization) (bool, error) { - if msg != nil { - if msg.Header.Author != batch.Author || msg.Header.Key != batch.Key { - log.L(ctx).Errorf("Mismatched key/author '%s'/'%s' on message entry %d in batch '%s'", msg.Header.Key, msg.Header.Author, i, batch.ID) - return false, nil // skip entry - } - msg.BatchID = batch.ID +func (em *eventManager) sentByUs(ctx context.Context, batch *fftypes.Batch) bool { + localNode := em.ni.GetNodeUUID(ctx) + if batch.Node == nil { + // This is from a node that hasn't yet completed registration, so we can't optimize + return false + } else if batch.Node.Equals(localNode) { + // We sent the batch, so we should already have all the messages and data locally + return true } + // We didn't send the batch, so all the data should be new - optimize the DB operations for that + return false +} - return em.persistReceivedMessage(ctx, i, msg, "batch", batch.ID, optimization) +func (em *eventManager) verifyAlreadyStored(ctx context.Context, batch *fftypes.Batch) (valid bool, err error) { + for _, msg := range batch.Payload.Messages { + msgLocal, _, _, err := em.data.GetMessageWithDataCached(ctx, msg.Header.ID) + if err != nil { + return false, err + } + if msgLocal == nil { + log.L(ctx).Errorf("Message entry %s in batch sent by this node, was not found", msg.Header.ID) + return false, nil + } + if !msgLocal.Hash.Equals(msg.Hash) { + log.L(ctx).Errorf("Message entry %s hash mismatch with already stored. Local=%s BatchMsg=%s", msg.Header.ID, msgLocal.Hash, msg.Hash) + return false, nil + } + } + return true, nil } -func (em *eventManager) persistReceivedMessage(ctx context.Context /* db TX context*/, i int, msg *fftypes.Message, mType string, mID *fftypes.UUID, optimization database.UpsertOptimization) (bool, error) { - l := log.L(ctx) - l.Tracef("%s '%s' message %d: %+v", mType, mID, i, msg) +func (em *eventManager) persistBatchContent(ctx context.Context, batch *fftypes.Batch, matchedMsgs []*messageAndData) (valid bool, err error) { - if msg == nil { - l.Errorf("null message entry %d in %s '%s'", i, mType, mID) - return false, nil // skip entry + // We want to insert the messages and data in the most efficient way we can. + // If we are sure we wrote the batch, then we do a cached lookup of each in turn - which is efficient + // because all of those should be in the cache as we wrote them recently. + if em.sentByUs(ctx, batch) { + allStored, err := em.verifyAlreadyStored(ctx, batch) + if err != nil { + return false, err + } + if allStored { + return true, nil + } + // Fall through otherwise + log.L(ctx).Warnf("Batch %s was sent by our UUID, but the content was not already stored. Assuming node has been reset", batch.ID) } - err := msg.Verify(ctx) + // Otherwise try a one-shot insert of all the data, on the basis it's likely unique + err = em.database.InsertDataArray(ctx, batch.Payload.Data) if err != nil { - l.Errorf("Invalid message entry %d in %s '%s': %s", i, mType, mID, err) - return false, nil // skip message entry + log.L(ctx).Debugf("Batch data insert optimization failed for batch '%s': %s", batch.ID, err) + // Fall back to individual upserts + for i, data := range batch.Payload.Data { + if err := em.database.UpsertData(ctx, data, database.UpsertOptimizationExisting); err != nil { + if err == database.HashMismatch { + log.L(ctx).Errorf("Invalid data entry %d in batch '%s'. Hash mismatch with existing record with same UUID '%s' Hash=%s", i, batch.ID, data.ID, data.Hash) + return false, nil + } + log.L(ctx).Errorf("Failed to insert data entry %d in batch '%s': %s", i, batch.ID, err) + return false, err + } + } } - // Insert the message, ensuring the hash doesn't change. - // We do not mark it as confirmed at this point, that's the job of the aggregator. - msg.State = fftypes.MessageStatePending - if err = em.database.UpsertMessage(ctx, msg, optimization); err != nil { - if err == database.HashMismatch { - l.Errorf("Invalid message entry %d in %s '%s'. Hash mismatch with existing record with same UUID '%s' Hash=%s", i, mType, mID, msg.Header.ID, msg.Hash) - return false, nil // This is not retryable. skip this data entry + // Then the same one-shot insert of all the mesages, on the basis they are likely unique (even if + // one of the data elements wasn't unique). Likely reasons for exceptions here are idempotent replay, + // or a root broadcast where "em.sentByUs" returned false, but we actually sent it. + err = em.database.InsertMessages(ctx, batch.Payload.Messages) + if err != nil { + log.L(ctx).Debugf("Batch message insert optimization failed for batch '%s': %s", batch.ID, err) + // Fall back to individual upserts + for i, msg := range batch.Payload.Messages { + if err = em.database.UpsertMessage(ctx, msg, database.UpsertOptimizationExisting); err != nil { + if err == database.HashMismatch { + log.L(ctx).Errorf("Invalid message entry %d in batch'%s'. Hash mismatch with existing record with same UUID '%s' Hash=%s", i, batch.ID, msg.Header.ID, msg.Hash) + return false, nil // This is not retryable. skip this data entry + } + log.L(ctx).Errorf("Failed to insert message entry %d in batch '%s': %s", i, batch.ID, err) + return false, err // a persistence failure here is considered retryable (so returned) + } } - l.Errorf("Failed to insert message entry %d in %s '%s': %s", i, mType, mID, err) - return false, err // a persistence failure here is considered retryable (so returned) } + // If all is well, update the cache before we return + for _, mm := range matchedMsgs { + em.data.UpdateMessageCache(mm.message, mm.data) + } return true, nil } diff --git a/internal/events/persist_batch_test.go b/internal/events/persist_batch_test.go index 4071348151..8a928fc7fd 100644 --- a/internal/events/persist_batch_test.go +++ b/internal/events/persist_batch_test.go @@ -22,6 +22,7 @@ import ( "testing" "github.com/hyperledger/firefly/mocks/databasemocks" + "github.com/hyperledger/firefly/mocks/datamocks" "github.com/hyperledger/firefly/pkg/database" "github.com/hyperledger/firefly/pkg/fftypes" "github.com/stretchr/testify/assert" @@ -97,75 +98,32 @@ func TestPersistBatchFromBroadcastNoCacheDataNotInBatch(t *testing.T) { mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil) mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationSkip).Return(nil) - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - SignerRef: fftypes.SignerRef{ - Author: "did:firefly:org/12345", - Key: "0x12345", - }, - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - ID: fftypes.NewUUID(), - Type: fftypes.TransactionTypeBatchPin, - }, - Messages: []*fftypes.Message{ - { - Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), - Type: fftypes.MessageTypeDefinition, - SignerRef: fftypes.SignerRef{ - Author: "did:firefly:org/12345", - Key: "0x12345", - }, - TxType: fftypes.TransactionTypeBatchPin, - }, - Data: fftypes.DataRefs{ - { - ID: fftypes.NewUUID(), - Hash: fftypes.NewRandB32(), - }, - }, - }, - }, - Data: nil, - }, - } - batch.Payload.Messages[0].Seal(em.ctx) + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + data.ID = fftypes.NewUUID() + _ = data.Seal(em.ctx, nil) batch.Hash = fftypes.HashString(batch.Manifest().String()) valid, err := em.persistBatchFromBroadcast(em.ctx, batch, batch.Hash) - assert.True(t, valid) + assert.False(t, valid) assert.NoError(t, err) } -func TestPersistBatchNilMessageEntryop(t *testing.T) { +func TestPersistBatchFromBroadcastExtraDataInBatch(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() mdi := em.database.(*databasemocks.Plugin) mdi.On("UpsertBatch", em.ctx, mock.Anything).Return(nil) + mdi.On("UpsertMessage", em.ctx, mock.Anything, database.UpsertOptimizationSkip).Return(nil) - batch := &fftypes.Batch{ - BatchHeader: fftypes.BatchHeader{ - ID: fftypes.NewUUID(), - SignerRef: fftypes.SignerRef{ - Author: "did:firefly:org/12345", - Key: "0x12345", - }, - }, - Payload: fftypes.BatchPayload{ - TX: fftypes.TransactionRef{ - ID: fftypes.NewUUID(), - Type: fftypes.TransactionTypeBatchPin, - }, - Messages: []*fftypes.Message{nil}, - Data: nil, - }, - } + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + data2 := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test2"`)} + _ = data2.Seal(em.ctx, nil) + batch.Payload.Data = append(batch.Payload.Data, data2) batch.Hash = fftypes.HashString(batch.Manifest().String()) valid, err := em.persistBatchFromBroadcast(em.ctx, batch, batch.Hash) @@ -174,6 +132,16 @@ func TestPersistBatchNilMessageEntryop(t *testing.T) { } +func TestPersistBatchNilMessageEntryop(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + valid := em.validateBatchMessage(em.ctx, &fftypes.Batch{}, 0, nil) + assert.False(t, valid) + +} + func TestPersistBatchFromBroadcastBadHash(t *testing.T) { em, cancel := newTestEventManager(t) @@ -190,3 +158,138 @@ func TestPersistBatchFromBroadcastBadHash(t *testing.T) { assert.False(t, ok) } + +func TestPersistBatchContentSendByUsOK(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Node = testNodeID + + mdm := em.data.(*datamocks.Manager) + mdm.On("GetMessageWithDataCached", em.ctx, batch.Payload.Messages[0].Header.ID).Return(batch.Payload.Messages[0], batch.Payload.Data, true, nil) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.NoError(t, err) + assert.True(t, ok) + + mdm.AssertExpectations(t) +} + +func TestPersistBatchContentSentByNil(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Node = nil + + mdi := em.database.(*databasemocks.Plugin) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertMessages", mock.Anything, mock.Anything).Return(nil) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.NoError(t, err) + assert.True(t, ok) + + mdi.AssertExpectations(t) + +} + +func TestPersistBatchContentSentByUsNotFoundFallback(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Node = testNodeID + + mdm := em.data.(*datamocks.Manager) + mdm.On("GetMessageWithDataCached", em.ctx, batch.Payload.Messages[0].Header.ID).Return(nil, nil, false, nil) + + mdi := em.database.(*databasemocks.Plugin) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertMessages", mock.Anything, mock.Anything).Return(nil) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.NoError(t, err) + assert.True(t, ok) + + mdm.AssertExpectations(t) + mdi.AssertExpectations(t) + +} + +func TestPersistBatchContentSentByUsFoundMismatch(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Node = testNodeID + + mdm := em.data.(*datamocks.Manager) + mdm.On("GetMessageWithDataCached", em.ctx, batch.Payload.Messages[0].Header.ID).Return(&fftypes.Message{ + Header: fftypes.MessageHeader{ + ID: fftypes.NewUUID(), + }, + }, nil, true, nil) + + mdi := em.database.(*databasemocks.Plugin) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertMessages", mock.Anything, mock.Anything).Return(fmt.Errorf("optimization miss")) + mdi.On("UpsertMessage", mock.Anything, mock.Anything, database.UpsertOptimizationExisting).Return(database.HashMismatch) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.NoError(t, err) + assert.False(t, ok) + + mdm.AssertExpectations(t) + mdi.AssertExpectations(t) + +} + +func TestPersistBatchContentSentByUsFoundError(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Node = testNodeID + + mdm := em.data.(*datamocks.Manager) + mdm.On("GetMessageWithDataCached", em.ctx, batch.Payload.Messages[0].Header.ID).Return(nil, nil, false, fmt.Errorf("pop")) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.Regexp(t, "pop", err) + assert.False(t, ok) + + mdm.AssertExpectations(t) + +} + +func TestPersistBatchContentDataHashMismatch(t *testing.T) { + + em, cancel := newTestEventManager(t) + defer cancel() + + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypeBroadcast, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + + mdi := em.database.(*databasemocks.Plugin) + mdi.On("InsertDataArray", mock.Anything, mock.Anything).Return(fmt.Errorf("optimization miss")) + mdi.On("UpsertData", mock.Anything, mock.Anything, database.UpsertOptimizationExisting).Return(database.HashMismatch) + + ok, err := em.persistBatchContent(em.ctx, batch, []*messageAndData{}) + assert.NoError(t, err) + assert.False(t, ok) + + mdi.AssertExpectations(t) + +} diff --git a/internal/i18n/en_translations.go b/internal/i18n/en_translations.go index 696d10486a..0a60a11bc1 100644 --- a/internal/i18n/en_translations.go +++ b/internal/i18n/en_translations.go @@ -291,5 +291,5 @@ var ( MsgFailedToRetrieve = ffm("FF10372", "Failed to retrieve %s %s", 500) MsgBlobMissingPublic = ffm("FF10373", "Blob for data %s missing public payload reference while flushing batch", 500) MsgDBMultiRowConfigError = ffm("FF10374", "Database invalid configuration - using multi-row insert on DB plugin that does not support query syntax for input") - MsgDBNoSequence = ffm("FF10375", "Failed to retrieve sequence for insert row %d", 500) + MsgDBNoSequence = ffm("FF10375", "Failed to retrieve sequence for insert row %d (could mean duplicate insert)", 500) ) diff --git a/mocks/datamocks/manager.go b/mocks/datamocks/manager.go index 1a8594774e..b9827008e8 100644 --- a/mocks/datamocks/manager.go +++ b/mocks/datamocks/manager.go @@ -193,6 +193,38 @@ func (_m *Manager) HydrateBatch(ctx context.Context, persistedBatch *fftypes.Bat return r0, r1 } +// PeekMessageCache provides a mock function with given fields: ctx, id, options +func (_m *Manager) PeekMessageCache(ctx context.Context, id *fftypes.UUID, options ...data.CacheReadOption) (*fftypes.Message, fftypes.DataArray) { + _va := make([]interface{}, len(options)) + for _i := range options { + _va[_i] = options[_i] + } + var _ca []interface{} + _ca = append(_ca, ctx, id) + _ca = append(_ca, _va...) + ret := _m.Called(_ca...) + + var r0 *fftypes.Message + if rf, ok := ret.Get(0).(func(context.Context, *fftypes.UUID, ...data.CacheReadOption) *fftypes.Message); ok { + r0 = rf(ctx, id, options...) + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(*fftypes.Message) + } + } + + var r1 fftypes.DataArray + if rf, ok := ret.Get(1).(func(context.Context, *fftypes.UUID, ...data.CacheReadOption) fftypes.DataArray); ok { + r1 = rf(ctx, id, options...) + } else { + if ret.Get(1) != nil { + r1 = ret.Get(1).(fftypes.DataArray) + } + } + + return r0, r1 +} + // ResolveInlineData provides a mock function with given fields: ctx, msg func (_m *Manager) ResolveInlineData(ctx context.Context, msg *data.NewMessage) error { ret := _m.Called(ctx, msg) diff --git a/pkg/fftypes/batch.go b/pkg/fftypes/batch.go index 3402c91fe1..89f828dbc7 100644 --- a/pkg/fftypes/batch.go +++ b/pkg/fftypes/batch.go @@ -91,7 +91,7 @@ type BatchPersisted struct { type BatchPayload struct { TX TransactionRef `json:"tx"` Messages []*Message `json:"messages"` - Data []*Data `json:"data"` + Data DataArray `json:"data"` } func (bm *BatchManifest) String() string { From edfaede213a7b384a4fac5ed8683285de5689c12 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 17:16:37 -0400 Subject: [PATCH 13/17] One pins SQL update per pin-batch Signed-off-by: Peter Broadhurst --- internal/database/sqlcommon/event_sql.go | 65 ++++++++++++++----- internal/database/sqlcommon/event_sql_test.go | 58 +++++++++++++++++ internal/database/sqlcommon/sqlcommon.go | 5 +- internal/events/aggregator_batch_state.go | 25 +++++-- .../events/aggregator_batch_state_test.go | 4 +- 5 files changed, 129 insertions(+), 28 deletions(-) diff --git a/internal/database/sqlcommon/event_sql.go b/internal/database/sqlcommon/event_sql.go index 95b8257c80..e6d01bd6a8 100644 --- a/internal/database/sqlcommon/event_sql.go +++ b/internal/database/sqlcommon/event_sql.go @@ -68,7 +68,24 @@ func (s *SQLCommon) InsertEvent(ctx context.Context, event *fftypes.Event) (err return s.commitTx(ctx, tx, autoCommit) } -func (s *SQLCommon) insertEventPreCommit(ctx context.Context, tx *txWrapper, event *fftypes.Event) (err error) { +func (s *SQLCommon) setEventInsertValues(query sq.InsertBuilder, event *fftypes.Event) sq.InsertBuilder { + return query.Values( + event.ID, + string(event.Type), + event.Namespace, + event.Reference, + event.Correlator, + event.Transaction, + event.Created, + ) +} + +func (s *SQLCommon) eventInserted(ctx context.Context, event *fftypes.Event) { + s.callbacks.OrderedUUIDCollectionNSEvent(database.CollectionEvents, fftypes.ChangeEventTypeCreated, event.Namespace, event.ID, event.Sequence) + log.L(ctx).Infof("Emitted %s event %s ref=%s (sequence=%d)", event.Type, event.ID, event.Reference, event.Sequence) +} + +func (s *SQLCommon) insertEventsPreCommit(ctx context.Context, tx *txWrapper, events []*fftypes.Event) (err error) { // We take the cost of a full table lock on the events table. // This allows us to rely on the sequence to always be increasing, even when writing events @@ -77,23 +94,35 @@ func (s *SQLCommon) insertEventPreCommit(ctx context.Context, tx *txWrapper, eve return err } - event.Sequence, err = s.insertTx(ctx, tx, - sq.Insert("events"). - Columns(eventColumns...). - Values( - event.ID, - string(event.Type), - event.Namespace, - event.Reference, - event.Correlator, - event.Transaction, - event.Created, - ), - func() { - s.callbacks.OrderedUUIDCollectionNSEvent(database.CollectionEvents, fftypes.ChangeEventTypeCreated, event.Namespace, event.ID, event.Sequence) - }, - ) - return err + if s.features.MultiRowInsert { + query := sq.Insert("events").Columns(eventColumns...) + for _, event := range events { + query = s.setEventInsertValues(query, event) + } + sequences := make([]int64, len(events)) + err := s.insertTxRows(ctx, tx, query, func() { + for i, event := range events { + event.Sequence = sequences[i] + s.eventInserted(ctx, event) + } + }, sequences, true /* we want the caller to be able to retry with individual upserts */) + if err != nil { + return err + } + } else { + // Fall back to individual inserts grouped in a TX + for _, event := range events { + query := s.setEventInsertValues(sq.Insert("events").Columns(eventColumns...), event) + event.Sequence, err = s.insertTx(ctx, tx, query, func() { + s.eventInserted(ctx, event) + }) + if err != nil { + return err + } + } + } + + return nil } func (s *SQLCommon) eventResult(ctx context.Context, row *sql.Rows) (*fftypes.Event, error) { diff --git a/internal/database/sqlcommon/event_sql_test.go b/internal/database/sqlcommon/event_sql_test.go index 3fce7b8e1d..1824feb960 100644 --- a/internal/database/sqlcommon/event_sql_test.go +++ b/internal/database/sqlcommon/event_sql_test.go @@ -146,6 +146,64 @@ func TestInsertEventFailCommit(t *testing.T) { assert.NoError(t, mock.ExpectationsWereMet()) } +func TestInsertEventsPreCommitMultiRowOK(t *testing.T) { + s, mock := newMockProvider().init() + s.features.MultiRowInsert = true + s.fakePSQLInsert = true + + ev1 := &fftypes.Event{ID: fftypes.NewUUID(), Namespace: "ns1"} + ev2 := &fftypes.Event{ID: fftypes.NewUUID(), Namespace: "ns1"} + s.callbacks.On("OrderedUUIDCollectionNSEvent", database.CollectionEvents, fftypes.ChangeEventTypeCreated, "ns1", ev1.ID, int64(1001)) + s.callbacks.On("OrderedUUIDCollectionNSEvent", database.CollectionEvents, fftypes.ChangeEventTypeCreated, "ns1", ev2.ID, int64(1002)) + + mock.ExpectBegin() + mock.ExpectExec("LOCK .*").WillReturnResult(driver.ResultNoRows) + mock.ExpectQuery("INSERT.*").WillReturnRows(sqlmock.NewRows([]string{sequenceColumn}). + AddRow(int64(1001)). + AddRow(int64(1002)), + ) + mock.ExpectCommit() + ctx, tx, autoCommit, err := s.beginOrUseTx(context.Background()) + tx.preCommitEvents = []*fftypes.Event{ev1, ev2} + assert.NoError(t, err) + err = s.commitTx(ctx, tx, autoCommit) + assert.NoError(t, err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + +func TestInsertEventsPreCommitMultiRowFail(t *testing.T) { + s, mock := newMockProvider().init() + s.features.MultiRowInsert = true + s.fakePSQLInsert = true + ev1 := &fftypes.Event{ID: fftypes.NewUUID(), Namespace: "ns1"} + mock.ExpectBegin() + mock.ExpectExec("LOCK .*").WillReturnResult(driver.ResultNoRows) + mock.ExpectQuery("INSERT.*").WillReturnError(fmt.Errorf("pop")) + ctx, tx, autoCommit, err := s.beginOrUseTx(context.Background()) + tx.preCommitEvents = []*fftypes.Event{ev1} + assert.NoError(t, err) + err = s.commitTx(ctx, tx, autoCommit) + assert.Regexp(t, "FF10116", err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + +func TestInsertEventsPreCommitSingleRowFail(t *testing.T) { + s, mock := newMockProvider().init() + ev1 := &fftypes.Event{ID: fftypes.NewUUID(), Namespace: "ns1"} + mock.ExpectBegin() + mock.ExpectExec("LOCK .*").WillReturnResult(driver.ResultNoRows) + mock.ExpectExec("INSERT.*").WillReturnError(fmt.Errorf("pop")) + ctx, tx, autoCommit, err := s.beginOrUseTx(context.Background()) + tx.preCommitEvents = []*fftypes.Event{ev1} + assert.NoError(t, err) + err = s.commitTx(ctx, tx, autoCommit) + assert.Regexp(t, "FF10116", err) + assert.NoError(t, mock.ExpectationsWereMet()) + s.callbacks.AssertExpectations(t) +} + func TestGetEventByIDSelectFail(t *testing.T) { s, mock := newMockProvider().init() eventID := fftypes.NewUUID() diff --git a/internal/database/sqlcommon/sqlcommon.go b/internal/database/sqlcommon/sqlcommon.go index f725787bd9..a725b83f6b 100644 --- a/internal/database/sqlcommon/sqlcommon.go +++ b/internal/database/sqlcommon/sqlcommon.go @@ -429,12 +429,11 @@ func (s *SQLCommon) commitTx(ctx context.Context, tx *txWrapper, autoCommit bool // Only at this stage do we write to the special events Database table, so we know // regardless of the higher level logic, the events are always written at this point // at the end of the transaction - for _, event := range tx.preCommitEvents { - if err := s.insertEventPreCommit(ctx, tx, event); err != nil { + if len(tx.preCommitEvents) > 0 { + if err := s.insertEventsPreCommit(ctx, tx, tx.preCommitEvents); err != nil { s.rollbackTx(ctx, tx, false) return err } - l.Infof("Emitted %s event %s ref=%s (sequence=%d)", event.Type, event.ID, event.Reference, event.Sequence) } l.Debugf(`SQL-> commit`) diff --git a/internal/events/aggregator_batch_state.go b/internal/events/aggregator_batch_state.go index 3153b5d993..25c5248805 100644 --- a/internal/events/aggregator_batch_state.go +++ b/internal/events/aggregator_batch_state.go @@ -266,14 +266,27 @@ func (bs *batchState) flushPins(ctx context.Context) error { // using the index range of pins it owns within the batch it is a part of. // Note that this might include pins not in the batch we read from the database, as the page size // cannot be guaranteed to overlap with the set of indexes of a message within a batch. + pinsDispatched := make(map[fftypes.UUID][]driver.Value) for _, dm := range bs.dispatchedMessages { - fb := database.PinQueryFactory.NewFilter(ctx) - filter := fb.And( - fb.Eq("batch", dm.batchID), - fb.Gte("index", dm.firstPinIndex), - fb.Lte("index", dm.lastPinIndex), - ) + batchDispatched := pinsDispatched[*dm.batchID] log.L(ctx).Debugf("Marking message dispatched batch=%s msg=%s firstIndex=%d lastIndex=%d", dm.batchID, dm.msgID, dm.firstPinIndex, dm.lastPinIndex) + for pinIndex := dm.firstPinIndex; pinIndex <= dm.lastPinIndex; pinIndex++ { + batchDispatched = append(batchDispatched, pinIndex) + } + if len(batchDispatched) > 0 { + pinsDispatched[*dm.batchID] = batchDispatched + } + } + // Build one uber update for DB efficiency + if len(pinsDispatched) > 0 { + fb := database.PinQueryFactory.NewFilter(ctx) + filter := fb.Or() + for batchID, batchDispached := range pinsDispatched { + filter.Condition(fb.And( + fb.Eq("batch", &batchID), + fb.In("index", batchDispached), + )) + } update := database.PinQueryFactory.NewUpdate(ctx).Set("dispatched", true) if err := bs.database.UpdatePins(ctx, filter, update); err != nil { return err diff --git a/internal/events/aggregator_batch_state_test.go b/internal/events/aggregator_batch_state_test.go index c35ec69783..5295020bc4 100644 --- a/internal/events/aggregator_batch_state_test.go +++ b/internal/events/aggregator_batch_state_test.go @@ -36,8 +36,10 @@ func TestFlushPinsFail(t *testing.T) { bs.MarkMessageDispatched(ag.ctx, fftypes.NewUUID(), &fftypes.Message{ Header: fftypes.MessageHeader{ - ID: fftypes.NewUUID(), + ID: fftypes.NewUUID(), + Topics: fftypes.FFStringArray{"topic1"}, }, + Pins: fftypes.FFStringArray{"pin1"}, }, 0) err := bs.flushPins(ag.ctx) From 7f1fb77c071393e7d04e60b9c0c591bd62c6d9a7 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Sun, 13 Mar 2022 18:10:37 -0400 Subject: [PATCH 14/17] Fixing unsafe use of pointer variable outside of loop Signed-off-by: Peter Broadhurst --- internal/batch/batch_processor.go | 18 ++++++++----- internal/database/sqlcommon/sqlcommon.go | 8 +++--- internal/events/aggregator.go | 12 +++++++-- internal/events/aggregator_batch_state.go | 23 +++++++++------- internal/events/aggregator_test.go | 31 +++++++++++++++++++--- internal/events/batch_pin_complete_test.go | 2 +- internal/events/dx_callbacks_test.go | 10 ++++++- pkg/fftypes/message.go | 23 ++++++++-------- pkg/fftypes/message_test.go | 2 -- pkg/fftypes/pin.go | 4 +-- pkg/fftypes/stringarray.go | 4 +-- pkg/fftypes/stringarray_test.go | 10 +++---- 12 files changed, 96 insertions(+), 51 deletions(-) diff --git a/internal/batch/batch_processor.go b/internal/batch/batch_processor.go index 86d43c11fe..62016f14bf 100644 --- a/internal/batch/batch_processor.go +++ b/internal/batch/batch_processor.go @@ -21,6 +21,7 @@ import ( "crypto/sha256" "database/sql/driver" "encoding/binary" + "fmt" "math" "sync" "time" @@ -412,7 +413,7 @@ func (bp *batchProcessor) initFlushState(id *fftypes.UUID, flushWork []*batchWor state.Payload.Messages = append(state.Payload.Messages, w.msg.BatchMessage()) } for _, d := range w.data { - log.L(bp.ctx).Debugf("Adding data '%s' to batch for message '%s'", d.ID, w.msg.Header.ID) + log.L(bp.ctx).Debugf("Adding data '%s' to batch '%s' for message '%s'", d.ID, id, w.msg.Header.ID) state.Payload.Data = append(state.Payload.Data, d.BatchData(state.Persisted.Type)) } } @@ -420,7 +421,7 @@ func (bp *batchProcessor) initFlushState(id *fftypes.UUID, flushWork []*batchWor return state } -func (bp *batchProcessor) maskContext(ctx context.Context, msg *fftypes.Message, topic string) (contextOrPin *fftypes.Bytes32, err error) { +func (bp *batchProcessor) maskContext(ctx context.Context, msg *fftypes.Message, topic string) (msgPinString string, contextOrPin *fftypes.Bytes32, err error) { hashBuilder := sha256.New() hashBuilder.Write([]byte(topic)) @@ -429,7 +430,7 @@ func (bp *batchProcessor) maskContext(ctx context.Context, msg *fftypes.Message, // of the topic. There would be no way to unmask it if we did, because we don't have // the full list of senders to know what their next hashes should be. if msg.Header.Group == nil { - return fftypes.HashResult(hashBuilder), nil + return "", fftypes.HashResult(hashBuilder), nil } // For private groups, we need to make the topic specific to the group (which is @@ -448,7 +449,7 @@ func (bp *batchProcessor) maskContext(ctx context.Context, msg *fftypes.Message, } err = bp.database.UpsertNonceNext(ctx, gc) if err != nil { - return nil, err + return "", nil, err } // Now combine our sending identity, and this nonce, to produce the hash that should @@ -459,7 +460,10 @@ func (bp *batchProcessor) maskContext(ctx context.Context, msg *fftypes.Message, binary.BigEndian.PutUint64(nonceBytes, uint64(gc.Nonce)) hashBuilder.Write(nonceBytes) - return fftypes.HashResult(hashBuilder), err + pin := fftypes.HashResult(hashBuilder) + pinStr := fmt.Sprintf("%s:%.16d", pin, gc.Nonce) + log.L(ctx).Debugf("Assigned pin '%s' to message %s for topic '%s'", pinStr, msg.Header.ID, topic) + return pinStr, pin, err } func (bp *batchProcessor) maskContexts(ctx context.Context, payload *fftypes.BatchPayload) ([]*fftypes.Bytes32, error) { @@ -473,13 +477,13 @@ func (bp *batchProcessor) maskContexts(ctx context.Context, payload *fftypes.Bat continue } for _, topic := range msg.Header.Topics { - contextOrPin, err := bp.maskContext(ctx, msg, topic) + pinString, contextOrPin, err := bp.maskContext(ctx, msg, topic) if err != nil { return nil, err } contextsOrPins = append(contextsOrPins, contextOrPin) if msg.Header.Group != nil { - msg.Pins = append(msg.Pins, contextOrPin.String()) + msg.Pins = append(msg.Pins, pinString /* contains the nonce as well as the pin hash */) pinsAssigned = true } } diff --git a/internal/database/sqlcommon/sqlcommon.go b/internal/database/sqlcommon/sqlcommon.go index a725b83f6b..990d01c05c 100644 --- a/internal/database/sqlcommon/sqlcommon.go +++ b/internal/database/sqlcommon/sqlcommon.go @@ -281,8 +281,8 @@ func (s *SQLCommon) insertTxRows(ctx context.Context, tx *txWrapper, q sq.Insert if err != nil { return i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } - l.Debugf(`SQL-> insert: %s`, shortenSQL(sqlQuery)) - l.Tracef(`SQL-> insert args: %+v`, args) + l.Debugf(`SQL-> insert %s`, shortenSQL(sqlQuery)) + l.Tracef(`SQL-> insert query: %s (args: %+v)`, sqlQuery, args) if useQuery { result, err := tx.sqlTX.QueryContext(ctx, sqlQuery, args...) for i := 0; i < len(sequences) && err == nil; i++ { @@ -329,7 +329,7 @@ func (s *SQLCommon) deleteTx(ctx context.Context, tx *txWrapper, q sq.DeleteBuil return i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } l.Debugf(`SQL-> delete: %s`, shortenSQL(sqlQuery)) - l.Tracef(`SQL-> delete args: %+v`, args) + l.Debugf(`SQL-> delete args: %+v`, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { l.Errorf(`SQL delete failed: %s sql=[ %s ]: %s`, err, sqlQuery, err) @@ -354,7 +354,7 @@ func (s *SQLCommon) updateTx(ctx context.Context, tx *txWrapper, q sq.UpdateBuil return -1, i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } l.Debugf(`SQL-> update: %s`, shortenSQL(sqlQuery)) - l.Tracef(`SQL-> update args: %+v`, args) + l.Debugf(`SQL-> update query: %s (args: %+v)`, sqlQuery, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { l.Errorf(`SQL update failed: %s sql=[ %s ]`, err, sqlQuery) diff --git a/internal/events/aggregator.go b/internal/events/aggregator.go index a8f3144ecb..b19e4143a7 100644 --- a/internal/events/aggregator.go +++ b/internal/events/aggregator.go @@ -20,6 +20,7 @@ import ( "context" "crypto/sha256" "database/sql/driver" + "strings" "github.com/hyperledger/firefly/internal/config" "github.com/hyperledger/firefly/internal/data" @@ -364,12 +365,19 @@ func (ag *aggregator) processMessage(ctx context.Context, manifest *fftypes.Batc } for i, pinStr := range msg.Pins { var msgContext fftypes.Bytes32 - err := msgContext.UnmarshalText([]byte(pinStr)) + pinSplit := strings.Split(pinStr, ":") + nonceStr := "" + if len(pinSplit) > 1 { + // We introduced a "HASH:NONCE" syntax into the pin strings, to aid debug, but the inclusion of the + // nonce after the hash is not necessary. + nonceStr = pinSplit[1] + } + err := msgContext.UnmarshalText([]byte(pinSplit[0])) if err != nil { l.Errorf("Message '%s' in batch '%s' has invalid pin at index %d: '%s'", msg.Header.ID, manifest.ID, i, pinStr) return nil } - nextPin, err := state.CheckMaskedContextReady(ctx, msg, msg.Header.Topics[i], pin.Sequence, &msgContext) + nextPin, err := state.CheckMaskedContextReady(ctx, msg, msg.Header.Topics[i], pin.Sequence, &msgContext, nonceStr) if err != nil || nextPin == nil { return err } diff --git a/internal/events/aggregator_batch_state.go b/internal/events/aggregator_batch_state.go index 25c5248805..164b5497c8 100644 --- a/internal/events/aggregator_batch_state.go +++ b/internal/events/aggregator_batch_state.go @@ -72,7 +72,8 @@ type dispatchedMessage struct { batchID *fftypes.UUID msgID *fftypes.UUID firstPinIndex int64 - lastPinIndex int64 + topicCount int + msgPins fftypes.FFStringArray } // batchState is the object that tracks the in-memory state that builds up while processing a batch of pins, @@ -176,7 +177,7 @@ func (bs *batchState) CheckUnmaskedContextReady(ctx context.Context, contextUnma } -func (bs *batchState) CheckMaskedContextReady(ctx context.Context, msg *fftypes.Message, topic string, firstMsgPinSequence int64, pin *fftypes.Bytes32) (*nextPinState, error) { +func (bs *batchState) CheckMaskedContextReady(ctx context.Context, msg *fftypes.Message, topic string, firstMsgPinSequence int64, pin *fftypes.Bytes32, nonceStr string) (*nextPinState, error) { l := log.L(ctx) // For masked pins, we can only process if: @@ -212,7 +213,7 @@ func (bs *batchState) CheckMaskedContextReady(ctx context.Context, msg *fftypes. l.Debugf("NextPin: context=%s author=%s nonce=%d hash=%s", np.Context, np.Identity, np.Nonce, np.Hash) } } - l.Warnf("Mismatched nexthash or author group=%s topic=%s context=%s pin=%s nextHash=%+v author=%s", msg.Header.Group, topic, contextUnmasked, pin, nextPin, msg.Header.Author) + l.Warnf("Mismatched nexthash or author group=%s topic=%s context=%s pin=%s nonce=%s nextHash=%+v author=%s", msg.Header.Group, topic, contextUnmasked, pin, nonceStr, nextPin, msg.Header.Author) return nil, nil } return &nextPinState{ @@ -226,7 +227,8 @@ func (bs *batchState) MarkMessageDispatched(ctx context.Context, batchID *fftype batchID: batchID, msgID: msg.Header.ID, firstPinIndex: msgBaseIndex, - lastPinIndex: msgBaseIndex + int64(len(msg.Header.Topics)) - 1, + topicCount: len(msg.Header.Topics), + msgPins: msg.Pins, }) } @@ -242,6 +244,7 @@ func (bs *batchState) SetContextBlockedBy(ctx context.Context, unmaskedContext f } func (bs *batchState) flushPins(ctx context.Context) error { + l := log.L(ctx) // Update all the next pins for _, npg := range bs.maskedContexts { @@ -269,9 +272,9 @@ func (bs *batchState) flushPins(ctx context.Context) error { pinsDispatched := make(map[fftypes.UUID][]driver.Value) for _, dm := range bs.dispatchedMessages { batchDispatched := pinsDispatched[*dm.batchID] - log.L(ctx).Debugf("Marking message dispatched batch=%s msg=%s firstIndex=%d lastIndex=%d", dm.batchID, dm.msgID, dm.firstPinIndex, dm.lastPinIndex) - for pinIndex := dm.firstPinIndex; pinIndex <= dm.lastPinIndex; pinIndex++ { - batchDispatched = append(batchDispatched, pinIndex) + l.Debugf("Marking message dispatched batch=%s msg=%s firstIndex=%d topics=%d pins=%s", dm.batchID, dm.msgID, dm.firstPinIndex, dm.topicCount, dm.msgPins) + for i := 0; i < dm.topicCount; i++ { + batchDispatched = append(batchDispatched, dm.firstPinIndex+int64(i)) } if len(batchDispatched) > 0 { pinsDispatched[*dm.batchID] = batchDispatched @@ -281,10 +284,10 @@ func (bs *batchState) flushPins(ctx context.Context) error { if len(pinsDispatched) > 0 { fb := database.PinQueryFactory.NewFilter(ctx) filter := fb.Or() - for batchID, batchDispached := range pinsDispatched { + for batchID, indexes := range pinsDispatched { filter.Condition(fb.And( - fb.Eq("batch", &batchID), - fb.In("index", batchDispached), + fb.Eq("batch", batchID), + fb.In("index", indexes), )) } update := database.PinQueryFactory.NewUpdate(ctx).Set("dispatched", true) diff --git a/internal/events/aggregator_test.go b/internal/events/aggregator_test.go index eefec9d436..27190bf544 100644 --- a/internal/events/aggregator_test.go +++ b/internal/events/aggregator_test.go @@ -21,6 +21,7 @@ import ( "crypto/sha256" "encoding/json" "fmt" + "io/ioutil" "testing" "github.com/hyperledger/firefly/internal/config" @@ -170,7 +171,7 @@ func TestAggregationMaskedZeroNonceMatch(t *testing.T) { Key: member2key, }, }, - Pins: []string{member2NonceZero.String()}, + Pins: []string{fmt.Sprintf("%s:%.9d", member2NonceZero, 0)}, Data: fftypes.DataRefs{ {ID: fftypes.NewUUID()}, }, @@ -1067,7 +1068,9 @@ func TestProcessMsgFailPinUpdate(t *testing.T) { mdi.On("UpdateMessage", ag.ctx, mock.Anything, mock.Anything).Return(nil) mdi.On("UpdateNextPin", ag.ctx, mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) - err := ag.processMessage(ag.ctx, &fftypes.BatchManifest{}, &fftypes.Pin{Masked: true, Sequence: 12345, Signer: "0x12345"}, 10, &fftypes.MessageManifestEntry{ + err := ag.processMessage(ag.ctx, &fftypes.BatchManifest{ + ID: fftypes.NewUUID(), + }, &fftypes.Pin{Masked: true, Sequence: 12345, Signer: "0x12345"}, 10, &fftypes.MessageManifestEntry{ MessageRef: fftypes.MessageRef{ ID: msg.Header.ID, Hash: msg.Hash, @@ -1101,7 +1104,7 @@ func TestCheckMaskedContextReadyMismatchedAuthor(t *testing.T) { Key: "0x12345", }, }, - }, "topic1", 12345, fftypes.NewRandB32()) + }, "topic1", 12345, fftypes.NewRandB32(), "12345") assert.NoError(t, err) } @@ -2185,3 +2188,25 @@ func TestMigrateManifestFail(t *testing.T) { assert.Nil(t, manifest) } + +func TestExtractBatchMessagePin(t *testing.T) { + ag, cancel := newTestAggregator() + defer cancel() + + b, err := ioutil.ReadFile("/tmp/4ba80bc9-28c3-494a-84a0-a6ae2d647f96.batch.json") + assert.NoError(t, err) + var bp fftypes.BatchPersisted + err = json.Unmarshal(b, &bp) + assert.NoError(t, err) + + var manifest *fftypes.BatchManifest + err = bp.Manifest.Unmarshal(context.Background(), &manifest) + assert.NoError(t, err) + + totalBatchPins, msgEntry, msgBaseIndex := ag.extractBatchMessagePin(manifest, 100) + assert.Equal(t, int64(len(manifest.Messages)), totalBatchPins) + assert.Equal(t, "86f4a5c8-e7ad-4df1-8af9-ff5f8f579827", msgEntry.ID.String()) + assert.Equal(t, int64(100), msgBaseIndex) + + // b7a08c51-ef24-4afd-8da2-f85568ae8208 was the one that we dispatched for 100 +} diff --git a/internal/events/batch_pin_complete_test.go b/internal/events/batch_pin_complete_test.go index f5ccd87df6..7e9a05c47c 100644 --- a/internal/events/batch_pin_complete_test.go +++ b/internal/events/batch_pin_complete_test.go @@ -75,7 +75,7 @@ func sampleBatch(t *testing.T, batchType fftypes.BatchType, txType fftypes.Trans } err := msg.Seal(context.Background()) assert.NoError(t, err) - batch.Hash = batch.Payload.Hash() + batch.Hash = fftypes.HashString(batch.Manifest().String()) return batch } diff --git a/internal/events/dx_callbacks_test.go b/internal/events/dx_callbacks_test.go index 04776a9add..f20f5ad454 100644 --- a/internal/events/dx_callbacks_test.go +++ b/internal/events/dx_callbacks_test.go @@ -116,7 +116,15 @@ func TestMessageReceiveOkBadBatchIgnored(t *testing.T) { em, cancel := newTestEventManager(t) defer cancel() - _, b := sampleBatchTransfer(t, fftypes.TransactionTypeTokenPool) + data := &fftypes.Data{ID: fftypes.NewUUID(), Value: fftypes.JSONAnyPtr(`"test"`)} + batch := sampleBatch(t, fftypes.BatchTypePrivate, fftypes.TransactionTypeBatchPin, fftypes.DataArray{data}) + batch.Payload.TX.Type = fftypes.TransactionTypeTokenPool + b, _ := json.Marshal(&fftypes.TransportWrapper{ + Batch: batch, + Group: &fftypes.Group{ + Hash: fftypes.NewRandB32(), + }, + }) org1 := newTestOrg("org1") node1 := newTestNode("node1", org1) diff --git a/pkg/fftypes/message.go b/pkg/fftypes/message.go index c5825b24ff..02a500c4b5 100644 --- a/pkg/fftypes/message.go +++ b/pkg/fftypes/message.go @@ -182,14 +182,6 @@ func (m *Message) Seal(ctx context.Context) (err error) { if len(m.Header.Topics) == 0 { m.Header.Topics = []string{DefaultTopic} } - if err := m.Header.Topics.Validate(ctx, "header.topics", true); err != nil { - return err - } - if m.Header.Tag != "" { - if err := ValidateFFNameField(ctx, m.Header.Tag, "header.tag"); err != nil { - return err - } - } if m.Header.ID == nil { m.Header.ID = NewUUID() } @@ -200,7 +192,10 @@ func (m *Message) Seal(ctx context.Context) (err error) { if m.Data == nil { m.Data = DataRefs{} } - err = m.DupDataCheck(ctx) + if m.Header.TxType == "" { + m.Header.TxType = TransactionTypeBatchPin + } + err = m.VerifyFields(ctx) if err == nil { m.Header.DataHash = m.Data.Hash() m.Hash = m.Header.Hash() @@ -223,14 +218,14 @@ func (m *Message) DupDataCheck(ctx context.Context) (err error) { return nil } -func (m *Message) Verify(ctx context.Context) error { +func (m *Message) VerifyFields(ctx context.Context) error { switch m.Header.TxType { case TransactionTypeBatchPin: case TransactionTypeUnpinned: default: return i18n.NewError(ctx, i18n.MsgInvalidTXTypeForMessage, m.Header.TxType) } - if err := m.Header.Topics.Validate(ctx, "header.topics", true); err != nil { + if err := m.Header.Topics.Validate(ctx, "header.topics", true, 10 /* Pins need 96 chars each*/); err != nil { return err } if m.Header.Tag != "" { @@ -238,7 +233,11 @@ func (m *Message) Verify(ctx context.Context) error { return err } } - err := m.DupDataCheck(ctx) + return m.DupDataCheck(ctx) +} + +func (m *Message) Verify(ctx context.Context) error { + err := m.VerifyFields(ctx) if err != nil { return err } diff --git a/pkg/fftypes/message_test.go b/pkg/fftypes/message_test.go index 4fe153c7d1..6c7dc489e3 100644 --- a/pkg/fftypes/message_test.go +++ b/pkg/fftypes/message_test.go @@ -85,8 +85,6 @@ func TestVerifyTXType(t *testing.T) { msg.Header.TxType = TransactionTypeTokenPool err = msg.Seal(context.Background()) - assert.NoError(t, err) - err = msg.Verify(context.Background()) assert.Regexp(t, "FF10343", err) } diff --git a/pkg/fftypes/pin.go b/pkg/fftypes/pin.go index f58a5f2475..9cfc240511 100644 --- a/pkg/fftypes/pin.go +++ b/pkg/fftypes/pin.go @@ -37,11 +37,11 @@ package fftypes // This is because the sequence must be in the order the pins arrive. // type Pin struct { - Sequence int64 `json:"sequence,omitempty"` + Sequence int64 `json:"sequence"` Masked bool `json:"masked,omitempty"` Hash *Bytes32 `json:"hash,omitempty"` Batch *UUID `json:"batch,omitempty"` - Index int64 `json:"index,omitempty"` + Index int64 `json:"index"` Dispatched bool `json:"dispatched,omitempty"` Signer string `json:"signer,omitempty"` Created *FFTime `json:"created,omitempty"` diff --git a/pkg/fftypes/stringarray.go b/pkg/fftypes/stringarray.go index 242315feff..2761dcfbbf 100644 --- a/pkg/fftypes/stringarray.go +++ b/pkg/fftypes/stringarray.go @@ -87,7 +87,7 @@ func (sa FFStringArray) String() string { return strings.Join([]string(sa), ",") } -func (sa FFStringArray) Validate(ctx context.Context, fieldName string, isName bool) error { +func (sa FFStringArray) Validate(ctx context.Context, fieldName string, isName bool, maxItems int) error { var totalLength int dupCheck := make(map[string]bool) for i, n := range sa { @@ -106,7 +106,7 @@ func (sa FFStringArray) Validate(ctx context.Context, fieldName string, isName b } } } - if isName && len(sa) > FFStringNameItemsMax { + if maxItems > 0 && len(sa) > maxItems { return i18n.NewError(ctx, i18n.MsgTooManyItems, fieldName, FFStringNameItemsMax, len(sa)) } if totalLength > FFStringArrayStandardMax { diff --git a/pkg/fftypes/stringarray_test.go b/pkg/fftypes/stringarray_test.go index c8be55bdb1..9c5af55132 100644 --- a/pkg/fftypes/stringarray_test.go +++ b/pkg/fftypes/stringarray_test.go @@ -30,25 +30,25 @@ func TestFFStringArrayVerifyTooLong(t *testing.T) { for i := 0; i < 16; i++ { na[i] = fmt.Sprintf("item_%d", i) } - err := na.Validate(context.Background(), "field1", true) + err := na.Validate(context.Background(), "field1", true, FFStringNameItemsMax) assert.Regexp(t, `FF10227.*field1`, err) } func TestFFStringArrayVerifyDuplicate(t *testing.T) { na := FFStringArray{"value1", "value2", "value1"} - err := na.Validate(context.Background(), "field1", true) + err := na.Validate(context.Background(), "field1", true, FFStringNameItemsMax) assert.Regexp(t, `FF10228.*field1`, err) } func TestFFStringArrayVerifyBadName(t *testing.T) { na := FFStringArray{"!valid"} - err := na.Validate(context.Background(), "field1", true) + err := na.Validate(context.Background(), "field1", true, FFStringNameItemsMax) assert.Regexp(t, `FF10131.*field1\[0\]`, err) } func TestFFStringArrayVerifyBadNonName(t *testing.T) { na := FFStringArray{"!valid"} - err := na.Validate(context.Background(), "field1", false) + err := na.Validate(context.Background(), "field1", false, FFStringNameItemsMax) assert.Regexp(t, `FF10335.*field1\[0\]`, err) } @@ -58,7 +58,7 @@ func TestFFStringArrayVerifyTooLongTotal(t *testing.T) { longstr.WriteRune('a') } na := FFStringArray{longstr.String()} - err := na.Validate(context.Background(), "field1", false) + err := na.Validate(context.Background(), "field1", false, FFStringNameItemsMax) assert.Regexp(t, `FF10188.*field1`, err) } From 0d5b479d1d79d643536c4a918f3acb0d45726fdb Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Mon, 14 Mar 2022 00:31:40 -0400 Subject: [PATCH 15/17] Optimize event loop for aggregator and subscriptions Signed-off-by: Peter Broadhurst --- internal/config/config.go | 2 +- internal/database/sqlcommon/message_sql.go | 2 +- internal/database/sqlcommon/sqlcommon.go | 4 +- internal/events/aggregator.go | 4 +- internal/events/aggregator_test.go | 46 +++++++---- internal/events/event_dispatcher.go | 15 +--- internal/events/event_dispatcher_test.go | 95 +--------------------- internal/events/event_poller.go | 72 ++++++++++------ internal/events/event_poller_test.go | 38 +++++++++ 9 files changed, 131 insertions(+), 147 deletions(-) diff --git a/internal/config/config.go b/internal/config/config.go index 6df3367385..2996f63885 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -327,7 +327,7 @@ func Reset() { viper.SetDefault(string(DataexchangeType), "https") viper.SetDefault(string(DebugPort), -1) viper.SetDefault(string(EventAggregatorFirstEvent), fftypes.SubOptsFirstEventOldest) - viper.SetDefault(string(EventAggregatorBatchSize), 50) + viper.SetDefault(string(EventAggregatorBatchSize), 200) viper.SetDefault(string(EventAggregatorBatchTimeout), "250ms") viper.SetDefault(string(EventAggregatorPollTimeout), "30s") viper.SetDefault(string(EventAggregatorRetryFactor), 2.0) diff --git a/internal/database/sqlcommon/message_sql.go b/internal/database/sqlcommon/message_sql.go index 7bc58bfa5b..b27fbd7085 100644 --- a/internal/database/sqlcommon/message_sql.go +++ b/internal/database/sqlcommon/message_sql.go @@ -504,7 +504,7 @@ func (s *SQLCommon) GetMessages(ctx context.Context, filter database.Filter) (me query, fop, fi, err := s.filterSelect(ctx, "", sq.Select(cols...).From("messages"), filter, msgFilterFieldMap, []interface{}{ &database.SortField{Field: "confirmed", Descending: true, Nulls: database.NullsFirst}, - "created", + &database.SortField{Field: "created", Descending: true}, }) if err != nil { return nil, nil, err diff --git a/internal/database/sqlcommon/sqlcommon.go b/internal/database/sqlcommon/sqlcommon.go index 990d01c05c..777486e866 100644 --- a/internal/database/sqlcommon/sqlcommon.go +++ b/internal/database/sqlcommon/sqlcommon.go @@ -329,7 +329,7 @@ func (s *SQLCommon) deleteTx(ctx context.Context, tx *txWrapper, q sq.DeleteBuil return i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } l.Debugf(`SQL-> delete: %s`, shortenSQL(sqlQuery)) - l.Debugf(`SQL-> delete args: %+v`, args) + l.Tracef(`SQL-> delete query: %s args: %+v`, sqlQuery, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { l.Errorf(`SQL delete failed: %s sql=[ %s ]: %s`, err, sqlQuery, err) @@ -354,7 +354,7 @@ func (s *SQLCommon) updateTx(ctx context.Context, tx *txWrapper, q sq.UpdateBuil return -1, i18n.WrapError(ctx, err, i18n.MsgDBQueryBuildFailed) } l.Debugf(`SQL-> update: %s`, shortenSQL(sqlQuery)) - l.Debugf(`SQL-> update query: %s (args: %+v)`, sqlQuery, args) + l.Tracef(`SQL-> update query: %s (args: %+v)`, sqlQuery, args) res, err := tx.sqlTX.ExecContext(ctx, sqlQuery, args...) if err != nil { l.Errorf(`SQL update failed: %s sql=[ %s ]`, err, sqlQuery) diff --git a/internal/events/aggregator.go b/internal/events/aggregator.go index b19e4143a7..5354fa69d5 100644 --- a/internal/events/aggregator.go +++ b/internal/events/aggregator.go @@ -291,8 +291,8 @@ func (ag *aggregator) processPins(ctx context.Context, pins []*fftypes.Pin, stat } } - err = ag.eventPoller.commitOffset(ctx, pins[len(pins)-1].Sequence) - return err + ag.eventPoller.commitOffset(pins[len(pins)-1].Sequence) + return nil } func (ag *aggregator) checkOnchainConsistency(ctx context.Context, msg *fftypes.Message, pin *fftypes.Pin) (valid bool, err error) { diff --git a/internal/events/aggregator_test.go b/internal/events/aggregator_test.go index 27190bf544..6ed71d0622 100644 --- a/internal/events/aggregator_test.go +++ b/internal/events/aggregator_test.go @@ -234,8 +234,6 @@ func TestAggregationMaskedZeroNonceMatch(t *testing.T) { return true })).Return(nil) - // Confirm the offset - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ { @@ -255,6 +253,9 @@ func TestAggregationMaskedZeroNonceMatch(t *testing.T) { assert.NotNil(t, bs.GetPendingConfirm()[*msgID]) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -354,8 +355,6 @@ func TestAggregationMaskedNextSequenceMatch(t *testing.T) { mdi.On("UpdatePins", ag.ctx, mock.Anything, mock.Anything).Return(nil) // Update the message mdi.On("UpdateMessage", ag.ctx, mock.Anything, mock.Anything).Return(nil) - // Confirm the offset - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) _, err := ag.processPinsEventsHandler([]fftypes.LocallySequenced{ &fftypes.Pin{ @@ -370,6 +369,9 @@ func TestAggregationMaskedNextSequenceMatch(t *testing.T) { }) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -439,8 +441,6 @@ func TestAggregationBroadcast(t *testing.T) { mdi.On("UpdatePins", ag.ctx, mock.Anything, mock.Anything).Return(nil) // Update the message mdi.On("UpdateMessage", ag.ctx, mock.Anything, mock.Anything).Return(nil) - // Confirm the offset - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ { @@ -457,6 +457,9 @@ func TestAggregationBroadcast(t *testing.T) { err = bs.RunFinalize(ag.ctx) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -532,8 +535,6 @@ func TestAggregationMigratedBroadcast(t *testing.T) { mdi.On("UpdatePins", ag.ctx, mock.Anything, mock.Anything).Return(nil) // Update the message mdi.On("UpdateMessage", ag.ctx, mock.Anything, mock.Anything).Return(nil) - // Confirm the offset - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err = ag.processPins(ag.ctx, []*fftypes.Pin{ { @@ -550,6 +551,9 @@ func TestAggregationMigratedBroadcast(t *testing.T) { err = bs.RunFinalize(ag.ctx) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -599,7 +603,6 @@ func TestAggregationMigratedBroadcastNilMessageID(t *testing.T) { } mdi.On("GetBatchByID", ag.ctx, batchID).Return(bp, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err = ag.processPins(ag.ctx, []*fftypes.Pin{ { @@ -616,6 +619,9 @@ func TestAggregationMigratedBroadcastNilMessageID(t *testing.T) { err = bs.RunFinalize(ag.ctx) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -663,7 +669,6 @@ func TestAggregationMigratedBroadcastInvalid(t *testing.T) { } mdi.On("GetBatchByID", ag.ctx, batchID).Return(bp, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ { @@ -680,6 +685,9 @@ func TestAggregationMigratedBroadcastInvalid(t *testing.T) { err = bs.RunFinalize(ag.ctx) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(10001), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) } @@ -743,13 +751,15 @@ func TestProcessPinsMissingBatch(t *testing.T) { mdi := ag.database.(*databasemocks.Plugin) mdi.On("GetBatchByID", ag.ctx, mock.Anything).Return(nil, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ {Sequence: 12345, Batch: fftypes.NewUUID()}, }, bs) assert.NoError(t, err) + // Confirm the offset + assert.Equal(t, int64(12345), <-ag.eventPoller.offsetCommitted) + } func TestProcessPinsMissingNoMsg(t *testing.T) { @@ -771,7 +781,6 @@ func TestProcessPinsMissingNoMsg(t *testing.T) { mdi := ag.database.(*databasemocks.Plugin) mdi.On("GetBatchByID", ag.ctx, mock.Anything).Return(bp, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ {Sequence: 12345, Batch: fftypes.NewUUID(), Index: 25}, @@ -779,6 +788,9 @@ func TestProcessPinsMissingNoMsg(t *testing.T) { assert.NoError(t, err) mdi.AssertExpectations(t) + // Confirm the offset + assert.Equal(t, int64(12345), <-ag.eventPoller.offsetCommitted) + } func TestProcessPinsBadMsgHeader(t *testing.T) { @@ -803,12 +815,15 @@ func TestProcessPinsBadMsgHeader(t *testing.T) { mdi := ag.database.(*databasemocks.Plugin) mdi.On("GetBatchByID", ag.ctx, mock.Anything).Return(bp, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) err := ag.processPins(ag.ctx, []*fftypes.Pin{ {Sequence: 12345, Batch: fftypes.NewUUID(), Index: 0}, }, bs) assert.NoError(t, err) + + // Confirm the offset + assert.Equal(t, int64(12345), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) } @@ -839,7 +854,6 @@ func TestProcessSkipDupMsg(t *testing.T) { mdi.On("GetPins", mock.Anything, mock.Anything).Return([]*fftypes.Pin{ {Sequence: 1111}, // blocks the context }, nil, nil) - mdi.On("UpdateOffset", ag.ctx, mock.Anything, mock.Anything, mock.Anything).Return(nil) mdm := ag.data.(*datamocks.Manager) mdm.On("GetMessageWithDataCached", ag.ctx, mock.Anything, data.CRORequirePublicBlobRefs).Return(batch.Payload.Messages[0], nil, true, nil) @@ -849,6 +863,10 @@ func TestProcessSkipDupMsg(t *testing.T) { {Sequence: 12345, Batch: batchID, Index: 1, Hash: fftypes.NewRandB32()}, }, bs) assert.NoError(t, err) + + // Confirm the offset + assert.Equal(t, int64(12345), <-ag.eventPoller.offsetCommitted) + mdi.AssertExpectations(t) mdm.AssertExpectations(t) diff --git a/internal/events/event_dispatcher.go b/internal/events/event_dispatcher.go index 7695ed1a24..b1a587578a 100644 --- a/internal/events/event_dispatcher.go +++ b/internal/events/event_dispatcher.go @@ -322,19 +322,13 @@ func (ed *eventDispatcher) bufferedDelivery(events []fftypes.LocallySequenced) ( nacks++ ed.handleNackOffsetUpdate(an) } else if nacks == 0 { - err := ed.handleAckOffsetUpdate(an) - if err != nil { - return false, err - } + ed.handleAckOffsetUpdate(an) lastAck = an.offset } } } if nacks == 0 && lastAck != highestOffset { - err := ed.eventPoller.commitOffset(ed.ctx, highestOffset) - if err != nil { - return false, err - } + ed.eventPoller.commitOffset(highestOffset) } return true, nil // poll again straight away for more messages } @@ -352,7 +346,7 @@ func (ed *eventDispatcher) handleNackOffsetUpdate(nack ackNack) { ed.inflight = map[fftypes.UUID]*fftypes.Event{} } -func (ed *eventDispatcher) handleAckOffsetUpdate(ack ackNack) error { +func (ed *eventDispatcher) handleAckOffsetUpdate(ack ackNack) { oldOffset := ed.eventPoller.getPollingOffset() ed.mux.Lock() delete(ed.inflight, ack.id) @@ -365,9 +359,8 @@ func (ed *eventDispatcher) handleAckOffsetUpdate(ack ackNack) error { ed.mux.Unlock() if (lowestInflight == -1 || lowestInflight > ack.offset) && ack.offset > oldOffset { // This was the lowest in flight, and we can move the offset forwards - return ed.eventPoller.commitOffset(ed.ctx, ack.offset) + ed.eventPoller.commitOffset(ack.offset) } - return nil } func (ed *eventDispatcher) dispatchChangeEvent(ce *fftypes.ChangeEvent) { diff --git a/internal/events/event_dispatcher_test.go b/internal/events/event_dispatcher_test.go index 5a43a2b90f..159fd9260a 100644 --- a/internal/events/event_dispatcher_test.go +++ b/internal/events/event_dispatcher_test.go @@ -157,6 +157,7 @@ func TestEventDispatcherReadAheadOutOfOrderAcks(t *testing.T) { ed, cancel := newTestEventDispatcher(sub) defer cancel() go ed.deliverEvents() + ed.eventPoller.offsetCommitted = make(chan int64, 3) mdi := ed.database.(*databasemocks.Plugin) mei := ed.transport.(*eventsmocks.PluginAll) mdm := ed.data.(*datamocks.Manager) @@ -177,15 +178,6 @@ func TestEventDispatcherReadAheadOutOfOrderAcks(t *testing.T) { ref4 := fftypes.NewUUID() ev4 := fftypes.NewUUID() - // Capture offset commits - offsetUpdates := make(chan int64) - uof := mdi.On("UpdateOffset", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil) - uof.RunFn = func(a mock.Arguments) { - f, err := a.Get(2).(database.Update).Finalize() - assert.NoError(t, err) - v, _ := f.SetOperations[0].Value.Value() - offsetUpdates <- v.(int64) - } // Setup enrichment mdm.On("GetMessageWithDataCached", mock.Anything, ref1).Return(&fftypes.Message{ Header: fftypes.MessageHeader{ID: ref1}, @@ -234,9 +226,9 @@ func TestEventDispatcherReadAheadOutOfOrderAcks(t *testing.T) { // Confirm we get the offset updates in the correct order, even though the confirmations // came in a different order from the app. - assert.Equal(t, int64(10000001), <-offsetUpdates) - assert.Equal(t, int64(10000003), <-offsetUpdates) - assert.Equal(t, int64(10000004), <-offsetUpdates) + assert.Equal(t, int64(10000001), <-ed.eventPoller.offsetCommitted) + assert.Equal(t, int64(10000003), <-ed.eventPoller.offsetCommitted) + assert.Equal(t, int64(10000004), <-ed.eventPoller.offsetCommitted) // This should complete the batch <-batch1Done @@ -919,52 +911,6 @@ func TestBufferedDeliveryNackRewind(t *testing.T) { assert.Equal(t, int64(100001), ed.eventPoller.pollingOffset) } -func TestBufferedDeliveryAckFail(t *testing.T) { - - sub := &subscription{ - definition: &fftypes.Subscription{}, - } - ed, cancel := newTestEventDispatcher(sub) - defer cancel() - go ed.deliverEvents() - ed.readAhead = 50 - - mdi := ed.database.(*databasemocks.Plugin) - mei := ed.transport.(*eventsmocks.PluginAll) - mdi.On("GetDataRefs", mock.Anything, mock.Anything).Return(nil, nil, nil) - mdi.On("UpdateOffset", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) - - delivered := make(chan bool) - deliver := mei.On("DeliveryRequest", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil) - deliver.RunFn = func(a mock.Arguments) { - delivered <- true - } - - bdDone := make(chan struct{}) - ev1 := fftypes.NewUUID() - ev2 := fftypes.NewUUID() - ed.eventPoller.pollingOffset = 100000 - go func() { - repoll, err := ed.bufferedDelivery([]fftypes.LocallySequenced{ - &fftypes.Event{ID: ev1, Sequence: 100001}, - &fftypes.Event{ID: ev2, Sequence: 100002}, - }) - assert.EqualError(t, err, "pop") - assert.False(t, repoll) - close(bdDone) - }() - - <-delivered - <-delivered - ed.deliveryResponse(&fftypes.EventDeliveryResponse{ - ID: ev1, - }) - - <-bdDone - assert.Equal(t, int64(100001), ed.eventPoller.pollingOffset) - -} - func TestBufferedDeliveryFailNack(t *testing.T) { log.SetLevel("trace") @@ -1012,39 +958,6 @@ func TestBufferedDeliveryFailNack(t *testing.T) { } -func TestBufferedFinalAckFail(t *testing.T) { - - sub := &subscription{ - definition: &fftypes.Subscription{}, - messageFilter: &messageFilter{ - topicsFilter: regexp.MustCompile("never matches"), - }, - transactionFilter: &transactionFilter{}, - blockchainFilter: &blockchainFilter{}, - } - ed, cancel := newTestEventDispatcher(sub) - defer cancel() - go ed.deliverEvents() - ed.readAhead = 50 - - mdi := ed.database.(*databasemocks.Plugin) - mdi.On("GetDataRefs", mock.Anything, mock.Anything).Return(nil, nil, nil) - mdi.On("UpdateOffset", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) - - ev1 := fftypes.NewUUID() - ev2 := fftypes.NewUUID() - ed.eventPoller.pollingOffset = 100000 - repoll, err := ed.bufferedDelivery([]fftypes.LocallySequenced{ - &fftypes.Event{ID: ev1, Sequence: 100001}, - &fftypes.Event{ID: ev2, Sequence: 100002}, - }) - assert.EqualError(t, err, "pop") - assert.False(t, repoll) - - assert.Equal(t, int64(100002), ed.eventPoller.pollingOffset) - -} - func TestAckNotInFlightNoop(t *testing.T) { sub := &subscription{ diff --git a/internal/events/event_poller.go b/internal/events/event_poller.go index 88211b63b7..7d80edfa2d 100644 --- a/internal/events/event_poller.go +++ b/internal/events/event_poller.go @@ -1,4 +1,4 @@ -// Copyright © 2021 Kaleido, Inc. +// Copyright © 2022 Kaleido, Inc. // // SPDX-License-Identifier: Apache-2.0 // @@ -29,15 +29,16 @@ import ( ) type eventPoller struct { - ctx context.Context - database database.Plugin - shoulderTaps chan bool - eventNotifier *eventNotifier - closed chan struct{} - offsetID int64 - pollingOffset int64 - mux sync.Mutex - conf *eventPollerConf + ctx context.Context + database database.Plugin + shoulderTaps chan bool + eventNotifier *eventNotifier + closed chan struct{} + offsetCommitted chan int64 + offsetID int64 + pollingOffset int64 + mux sync.Mutex + conf *eventPollerConf } type newEventsHandler func(events []fftypes.LocallySequenced) (bool, error) @@ -62,12 +63,13 @@ type eventPollerConf struct { func newEventPoller(ctx context.Context, di database.Plugin, en *eventNotifier, conf *eventPollerConf) *eventPoller { ep := &eventPoller{ - ctx: log.WithLogField(ctx, "role", fmt.Sprintf("ep[%s:%s]", conf.namespace, conf.offsetName)), - database: di, - shoulderTaps: make(chan bool, 1), - eventNotifier: en, - closed: make(chan struct{}), - conf: conf, + ctx: log.WithLogField(ctx, "role", fmt.Sprintf("ep[%s:%s]", conf.namespace, conf.offsetName)), + database: di, + shoulderTaps: make(chan bool, 1), + offsetCommitted: make(chan int64, 1), + eventNotifier: en, + closed: make(chan struct{}), + conf: conf, } if ep.conf.maybeRewind == nil { ep.conf.maybeRewind = func() (bool, int64) { return false, -1 } @@ -121,6 +123,7 @@ func (ep *eventPoller) start() { } go ep.newEventNotifications() go ep.eventLoop() + go ep.offsetCommitLoop() } func (ep *eventPoller) rewindPollingOffset(offset int64) { @@ -138,21 +141,20 @@ func (ep *eventPoller) getPollingOffset() int64 { return ep.pollingOffset } -func (ep *eventPoller) commitOffset(ctx context.Context, offset int64) error { +func (ep *eventPoller) commitOffset(offset int64) { // Next polling cycle should start one higher than this offset + ep.mux.Lock() ep.pollingOffset = offset + ep.mux.Unlock() - // Must be called from the event polling routine - l := log.L(ctx) // No persistence for ephemeral (non-durable) subscriptions if !ep.conf.ephemeral { - u := database.OffsetQueryFactory.NewUpdate(ep.ctx).Set("current", ep.pollingOffset) - if err := ep.database.UpdateOffset(ctx, ep.offsetID, u); err != nil { - return err + // We do this in the background, as it is an expensive full DB commit + select { + case ep.offsetCommitted <- offset: + default: } } - l.Debugf("Event polling offset committed %d", ep.pollingOffset) - return nil } func (ep *eventPoller) readPage() ([]fftypes.LocallySequenced, error) { @@ -187,7 +189,10 @@ func (ep *eventPoller) readPage() ([]fftypes.LocallySequenced, error) { func (ep *eventPoller) eventLoop() { l := log.L(ep.ctx) l.Debugf("Started event detector") - defer close(ep.closed) + defer func() { + close(ep.closed) + close(ep.offsetCommitted) + }() for { // Read messages from the DB - in an error condition we retry until success, or a closed context @@ -219,6 +224,23 @@ func (ep *eventPoller) eventLoop() { } } +func (ep *eventPoller) offsetCommitLoop() { + l := log.L(ep.ctx) + for range ep.offsetCommitted { + _ = ep.conf.retry.Do(ep.ctx, "process events", func(attempt int) (retry bool, err error) { + ep.mux.Lock() + pollingOffset := ep.pollingOffset + ep.mux.Unlock() + u := database.OffsetQueryFactory.NewUpdate(ep.ctx).Set("current", pollingOffset) + if err := ep.database.UpdateOffset(ep.ctx, ep.offsetID, u); err != nil { + return true, err + } + l.Debugf("Event polling offset committed %d", pollingOffset) + return false, nil + }) + } +} + func (ep *eventPoller) dispatchEventsRetry(events []fftypes.LocallySequenced) (repoll bool, err error) { err = ep.conf.retry.Do(ep.ctx, "process events", func(attempt int) (retry bool, err error) { repoll, err = ep.conf.newEventsHandler(events) diff --git a/internal/events/event_poller_test.go b/internal/events/event_poller_test.go index f6a5b60955..7d0bb91cb6 100644 --- a/internal/events/event_poller_test.go +++ b/internal/events/event_poller_test.go @@ -311,3 +311,41 @@ func TestDoubleTap(t *testing.T) { ep.shoulderTap() ep.shoulderTap() // this should not block } + +func TestDoubleConfirm(t *testing.T) { + mdi := &databasemocks.Plugin{} + ep, cancel := newTestEventPoller(t, mdi, nil, nil) + defer cancel() + ep.commitOffset(12345) + ep.commitOffset(12346) // this should not block +} + +func TestOffsetCommitLoopOk(t *testing.T) { + mdi := &databasemocks.Plugin{} + + ep, cancel := newTestEventPoller(t, mdi, nil, nil) + cancel() + + mdi.On("UpdateOffset", mock.Anything, ep.offsetID, mock.Anything).Return(nil) + + ep.offsetCommitted <- int64(12345) + close(ep.offsetCommitted) + ep.offsetCommitLoop() + + mdi.AssertExpectations(t) +} + +func TestOffsetCommitLoopFail(t *testing.T) { + mdi := &databasemocks.Plugin{} + + ep, cancel := newTestEventPoller(t, mdi, nil, nil) + cancel() + + mdi.On("UpdateOffset", mock.Anything, ep.offsetID, mock.Anything).Return(fmt.Errorf("pop")) + + ep.offsetCommitted <- int64(12345) + close(ep.offsetCommitted) + ep.offsetCommitLoop() + + mdi.AssertExpectations(t) +} From 80ed63861da18c4c9ca87d6433859220b0d6c9e5 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Mon, 14 Mar 2022 09:14:41 -0400 Subject: [PATCH 16/17] Update public blob refs in DB on batch processor finalization Signed-off-by: Peter Broadhurst --- internal/batch/batch_processor.go | 28 +++++++--- internal/batch/batch_processor_test.go | 77 ++++++++++++++++++++++++++ internal/broadcast/manager.go | 5 +- internal/broadcast/manager_test.go | 14 +++-- internal/events/aggregator_test.go | 23 -------- 5 files changed, 109 insertions(+), 38 deletions(-) diff --git a/internal/batch/batch_processor.go b/internal/batch/batch_processor.go index 62016f14bf..a1adc9c1ba 100644 --- a/internal/batch/batch_processor.go +++ b/internal/batch/batch_processor.go @@ -94,10 +94,11 @@ type batchProcessor struct { } type DispatchState struct { - Manifest *fftypes.BatchManifest - Persisted fftypes.BatchPersisted - Payload fftypes.BatchPayload - Pins []*fftypes.Bytes32 + Manifest *fftypes.BatchManifest + Persisted fftypes.BatchPersisted + Payload fftypes.BatchPayload + Pins []*fftypes.Bytes32 + BlobsPublished []*fftypes.UUID } const batchSizeEstimateBase = int64(512) @@ -371,10 +372,8 @@ func (bp *batchProcessor) flush(overflow bool) error { log.L(bp.ctx).Debugf("Sealed batch %s", id) // Dispatch phase: the heavy lifting work - calling plugins to do the hard work of the batch. - // Must manage its own database updates if it performs them, and any that result in updates - // to the payload must be reflected back on the payload objects. - // For example updates to the Blob.Public of a Data entry must be written do the DB, - // and updated in Payload.Data[] array. + // The dispatcher can update the state, such as appending to the BlobsPublished array, + // to affect DB updates as part of the finalization phase. err = bp.dispatchBatch(state) if err != nil { return err @@ -580,6 +579,19 @@ func (bp *batchProcessor) markPayloadDispatched(state *DispatchState) error { return err } + for _, dataID := range state.BlobsPublished { + for _, d := range state.Payload.Data { + if d.ID.Equals(dataID) { + dataUpdate := database.DataQueryFactory.NewUpdate(ctx). + Set("blob.public", state.Persisted.ID) + if err = bp.database.UpdateData(ctx, dataID, dataUpdate); err != nil { + return err + } + break + } + } + } + if bp.conf.txType == fftypes.TransactionTypeUnpinned { for _, msg := range state.Payload.Messages { // Emit a confirmation event locally immediately diff --git a/internal/batch/batch_processor_test.go b/internal/batch/batch_processor_test.go index 54c5f6865c..6ae24999c1 100644 --- a/internal/batch/batch_processor_test.go +++ b/internal/batch/batch_processor_test.go @@ -430,3 +430,80 @@ func TestMaskContextsUpdataMessageFail(t *testing.T) { mdi.AssertExpectations(t) } + +func TestDispatchWithPublicBlobUpdates(t *testing.T) { + log.SetLevel("debug") + config.Reset() + + dataID := fftypes.NewUUID() + dispatched := make(chan *DispatchState) + mdi, bp := newTestBatchProcessor(func(c context.Context, state *DispatchState) error { + state.BlobsPublished = append(state.BlobsPublished, dataID) + dispatched <- state + return nil + }) + bp.conf.BatchMaxSize = 1 + bp.conf.txType = fftypes.TransactionTypeUnpinned + + mockRunAsGroupPassthrough(mdi) + mdi.On("UpdateData", mock.Anything, dataID, mock.Anything).Return(nil) + mdi.On("UpdateMessages", mock.Anything, mock.Anything, mock.Anything).Return(nil) + mdi.On("UpsertBatch", mock.Anything, mock.Anything, mock.Anything).Return(nil) + mdi.On("InsertEvent", mock.Anything, mock.Anything).Return(nil) + + mth := bp.txHelper.(*txcommonmocks.Helper) + mth.On("SubmitNewTransaction", mock.Anything, "ns1", fftypes.TransactionTypeUnpinned).Return(fftypes.NewUUID(), nil) + + mdm := bp.data.(*datamocks.Manager) + mdm.On("UpdateMessageIfCached", mock.Anything, mock.Anything).Return() + + // Dispatch the work + go func() { + bp.newWork <- &batchWork{ + msg: &fftypes.Message{Header: fftypes.MessageHeader{ID: fftypes.NewUUID()}, Sequence: int64(1000)}, + data: fftypes.DataArray{ + {ID: dataID, Blob: &fftypes.BlobRef{ + Public: "public/ref", + }}, + }, + } + }() + + batch := <-dispatched + assert.Equal(t, 1, len(batch.Payload.Messages)) + + bp.cancelCtx() + <-bp.done + + mdi.AssertExpectations(t) + mdm.AssertExpectations(t) + mth.AssertExpectations(t) +} + +func TestDispatchWithPublicBlobUpdatesFail(t *testing.T) { + log.SetLevel("debug") + config.Reset() + + mdi, bp := newTestBatchProcessor(func(c context.Context, state *DispatchState) error { return nil }) + bp.cancelCtx() + + mockRunAsGroupPassthrough(mdi) + mdi.On("UpdateData", mock.Anything, mock.Anything, mock.Anything).Return(fmt.Errorf("pop")) + mdi.On("UpdateMessages", mock.Anything, mock.Anything, mock.Anything).Return(nil) + + data := &fftypes.Data{ + ID: fftypes.NewUUID(), + Blob: &fftypes.BlobRef{ + Public: "test/ref", + }, + } + err := bp.markPayloadDispatched(&DispatchState{ + Payload: fftypes.BatchPayload{ + Data: fftypes.DataArray{data}, + }, + BlobsPublished: []*fftypes.UUID{data.ID}, + }) + assert.Regexp(t, "FF10158", err) + + mdi.AssertExpectations(t) +} diff --git a/internal/broadcast/manager.go b/internal/broadcast/manager.go index 82674a4ec9..5505a8c935 100644 --- a/internal/broadcast/manager.go +++ b/internal/broadcast/manager.go @@ -124,7 +124,7 @@ func (bm *broadcastManager) Name() string { func (bm *broadcastManager) dispatchBatch(ctx context.Context, state *batch.DispatchState) error { // Ensure all the blobs are published - if err := bm.publishBlobs(ctx, state.Payload.Data); err != nil { + if err := bm.publishBlobs(ctx, state.Payload.Data, state); err != nil { return err } @@ -150,7 +150,7 @@ func (bm *broadcastManager) dispatchBatch(ctx context.Context, state *batch.Disp return bm.batchpin.SubmitPinnedBatch(ctx, &state.Persisted, state.Pins) } -func (bm *broadcastManager) publishBlobs(ctx context.Context, data fftypes.DataArray) error { +func (bm *broadcastManager) publishBlobs(ctx context.Context, data fftypes.DataArray, state *batch.DispatchState) error { for _, d := range data { // We only need to send a blob if there is one, and it's not been uploaded to the shared storage if d.Blob != nil && d.Blob.Hash != nil && d.Blob.Public == "" { @@ -174,6 +174,7 @@ func (bm *broadcastManager) publishBlobs(ctx context.Context, data fftypes.DataA if err != nil { return err } + state.BlobsPublished = append(state.BlobsPublished, d.ID) log.L(ctx).Infof("Published blob with hash '%s' for data '%s' to shared storage: '%s'", d.Blob.Hash, d.ID, d.Blob.Public) } } diff --git a/internal/broadcast/manager_test.go b/internal/broadcast/manager_test.go index 6e95c3c948..bf9a116f02 100644 --- a/internal/broadcast/manager_test.go +++ b/internal/broadcast/manager_test.go @@ -327,7 +327,8 @@ func TestPublishBlobsPublishOk(t *testing.T) { }, } - err := bm.publishBlobs(ctx, fftypes.DataArray{data}) + bs := &batch.DispatchState{} + err := bm.publishBlobs(ctx, fftypes.DataArray{data}, bs) assert.NoError(t, err) assert.Equal(t, "payload-ref1", data.Blob.Public) @@ -335,6 +336,9 @@ func TestPublishBlobsPublishOk(t *testing.T) { assert.NoError(t, err) assert.Equal(t, "some data", string(b)) + assert.Len(t, bs.BlobsPublished, 1) + assert.Equal(t, data.ID, bs.BlobsPublished[0]) + mdi.AssertExpectations(t) mdx.AssertExpectations(t) mps.AssertExpectations(t) @@ -370,7 +374,7 @@ func TestPublishBlobsPublishFail(t *testing.T) { Hash: blob.Hash, }, }, - }) + }, &batch.DispatchState{}) assert.EqualError(t, err, "pop") b, err := ioutil.ReadAll(capturedReader) @@ -406,7 +410,7 @@ func TestPublishBlobsDownloadFail(t *testing.T) { Hash: blob.Hash, }, }, - }) + }, &batch.DispatchState{}) assert.Regexp(t, "FF10240", err) mdi.AssertExpectations(t) @@ -435,7 +439,7 @@ func TestPublishBlobsGetBlobFail(t *testing.T) { Hash: blob.Hash, }, }, - }) + }, &batch.DispatchState{}) assert.Regexp(t, "pop", err) mdi.AssertExpectations(t) @@ -463,7 +467,7 @@ func TestPublishBlobsGetBlobNotFound(t *testing.T) { Hash: blob.Hash, }, }, - }) + }, &batch.DispatchState{}) assert.Regexp(t, "FF10239", err) mdi.AssertExpectations(t) diff --git a/internal/events/aggregator_test.go b/internal/events/aggregator_test.go index 6ed71d0622..a3f0a89b6c 100644 --- a/internal/events/aggregator_test.go +++ b/internal/events/aggregator_test.go @@ -21,7 +21,6 @@ import ( "crypto/sha256" "encoding/json" "fmt" - "io/ioutil" "testing" "github.com/hyperledger/firefly/internal/config" @@ -2206,25 +2205,3 @@ func TestMigrateManifestFail(t *testing.T) { assert.Nil(t, manifest) } - -func TestExtractBatchMessagePin(t *testing.T) { - ag, cancel := newTestAggregator() - defer cancel() - - b, err := ioutil.ReadFile("/tmp/4ba80bc9-28c3-494a-84a0-a6ae2d647f96.batch.json") - assert.NoError(t, err) - var bp fftypes.BatchPersisted - err = json.Unmarshal(b, &bp) - assert.NoError(t, err) - - var manifest *fftypes.BatchManifest - err = bp.Manifest.Unmarshal(context.Background(), &manifest) - assert.NoError(t, err) - - totalBatchPins, msgEntry, msgBaseIndex := ag.extractBatchMessagePin(manifest, 100) - assert.Equal(t, int64(len(manifest.Messages)), totalBatchPins) - assert.Equal(t, "86f4a5c8-e7ad-4df1-8af9-ff5f8f579827", msgEntry.ID.String()) - assert.Equal(t, int64(100), msgBaseIndex) - - // b7a08c51-ef24-4afd-8da2-f85568ae8208 was the one that we dispatched for 100 -} From 2ba519a99d341b696c706b107ab2a504f8a2f8f1 Mon Sep 17 00:00:00 2001 From: Peter Broadhurst Date: Tue, 15 Mar 2022 12:12:27 -0400 Subject: [PATCH 17/17] Address review comments Signed-off-by: Peter Broadhurst --- ff-perf.log | 1 - internal/database/sqlcommon/sqlcommon.go | 2 ++ pkg/database/plugin.go | 6 +++--- 3 files changed, 5 insertions(+), 4 deletions(-) delete mode 100644 ff-perf.log diff --git a/ff-perf.log b/ff-perf.log deleted file mode 100644 index 143a6bcc90..0000000000 --- a/ff-perf.log +++ /dev/null @@ -1 +0,0 @@ -nohup: ff-perf: No such file or directory diff --git a/internal/database/sqlcommon/sqlcommon.go b/internal/database/sqlcommon/sqlcommon.go index 777486e866..84be79a8c2 100644 --- a/internal/database/sqlcommon/sqlcommon.go +++ b/internal/database/sqlcommon/sqlcommon.go @@ -52,6 +52,8 @@ type txWrapper struct { tableLocks []string } +// shortenSQL grabs the first three words of a SQL statement, for minimal debug logging (SQL statements can be huge +// even without args in the example of a multi-row insert - so we reserve full logging for trace level only.) func shortenSQL(sqlString string) string { buff := strings.Builder{} spaceCount := 0 diff --git a/pkg/database/plugin.go b/pkg/database/plugin.go index 7a4f7ddbfb..5b07f5644d 100644 --- a/pkg/database/plugin.go +++ b/pkg/database/plugin.go @@ -77,7 +77,7 @@ type iMessageCollection interface { // must match the hash of the record that is being inserted. UpsertMessage(ctx context.Context, message *fftypes.Message, optimization UpsertOptimization) (err error) - // InsertMessages performs a batch insert of messages assured to be new records + // InsertMessages performs a batch insert of messages assured to be new records - fails if they already exist, so caller can fall back to upsert individually InsertMessages(ctx context.Context, messages []*fftypes.Message) (err error) // UpdateMessage - Update message @@ -109,7 +109,7 @@ type iDataCollection interface { // must match the hash of the record that is being inserted. UpsertData(ctx context.Context, data *fftypes.Data, optimization UpsertOptimization) (err error) - // InsertDataArray performs a batch insert of data assured to be new records + // InsertDataArray performs a batch insert of data assured to be new records - fails if they already exist, so caller can fall back to upsert individually InsertDataArray(ctx context.Context, data fftypes.DataArray) (err error) // UpdateData - Update data @@ -188,7 +188,7 @@ type iOffsetCollection interface { } type iPinCollection interface { - // InsertPins - Inserts a list of pins - fails if they already exist, so caller can fall back to UpsertPin individually + // InsertPins - Inserts a list of pins - fails if they already exist, so caller can fall back to upsert individually InsertPins(ctx context.Context, pins []*fftypes.Pin) (err error) // UpsertPin - Will insert a pin at the end of the sequence, unless the batch+hash+index sequence already exists