From 4e2e20b04db3c191f54dcec8075ba17f298f3217 Mon Sep 17 00:00:00 2001 From: Morgan Bauer Date: Wed, 22 Jan 2020 14:54:50 -0800 Subject: [PATCH] logging and better tests Signed-off-by: Morgan Bauer --- fab3/ethservice.go | 23 +++++++++++++--- fab3/ethservice_test.go | 58 ++++++++++++++++++++++++++++++++++------- fab3/filters.go | 26 ++++++++++-------- 3 files changed, 83 insertions(+), 24 deletions(-) diff --git a/fab3/ethservice.go b/fab3/ethservice.go index f612a777..91aba6a0 100644 --- a/fab3/ethservice.go +++ b/fab3/ethservice.go @@ -532,11 +532,20 @@ func (s *ethService) GetLogs(r *http.Request, args *types.GetLogsArgs, logs *[]t } func (s *ethService) NewFilter(_ *http.Request, filter *types.GetLogsArgs, result *string) error { + logger := s.logger.With("method", "NewFilter") + latestExistingBlock, err := s.parseBlockNum("latest") + if err != nil { + return errors.Wrap(err, "latest block number not available at this time") + } + s.filterMapLock.Lock() s.filterSeq++ index := s.filterSeq - s.filterMap[index] = &logsFilter{lastAccessTime: time.Now(), logArgs: filter} + s.filterMap[index] = &logsFilter{logArgs: filter, latestBlockSeen: latestExistingBlock, lastAccessTime: time.Now()} s.filterMapLock.Unlock() + + logger.Debugf("filter created with ID %d, log args %v", index, filter) + *result = "0x" + strconv.FormatUint(index, 16) return nil } @@ -555,6 +564,7 @@ func (s *ethService) UninstallFilter(_ *http.Request, filterID *types.FilterID, } func (s *ethService) NewBlockFilter(_ *http.Request, _ *interface{}, result *string) error { + logger := s.logger.With("method", "NewBlockFilter") latestExistingBlock, err := s.parseBlockNum("latest") if err != nil { return errors.Wrap(err, "latest block number not available at this time") @@ -563,9 +573,11 @@ func (s *ethService) NewBlockFilter(_ *http.Request, _ *interface{}, result *str s.filterMapLock.Lock() s.filterSeq++ index := s.filterSeq - s.filterMap[index] = &newBlockFilter{latestBlockSeen: latestExistingBlock, lastAccessTime: time.Now()} s.filterMapLock.Unlock() + + logger.Debugf("filter created with ID %d, current latest block %d", index, latestExistingBlock) + *result = "0x" + strconv.FormatUint(index, 16) return nil } @@ -600,6 +612,7 @@ func (s *ethService) GetFilterChanges(_ *http.Request, filterID *types.FilterID, } func (s *ethService) GetFilterLogs(_ *http.Request, filterID *types.FilterID, alwaysLogs *[]interface{}) error { + logger := s.logger.With("method", "GetFilterLogs") id := filterID.ID var f *logsFilter // get the filter @@ -619,8 +632,9 @@ func (s *ethService) GetFilterLogs(_ *http.Request, filterID *types.FilterID, al // remove the filter if not valid and return error // delegate to existing function var removed bool + logger.Debugf("expired filter ID:%d removed", id) s.UninstallFilter(nil, filterID, &removed) - return fmt.Errorf("U No filter found for id %d", id) + return fmt.Errorf("No filter found for id %d", id) } // use the filter var logs []types.Log @@ -629,11 +643,12 @@ func (s *ethService) GetFilterLogs(_ *http.Request, filterID *types.FilterID, al return errors.Wrapf(err, "failed to run filter id: %d", id) } l := make([]interface{}, 0, len(logs)) + logger.Debug(len(logs)) for _, v := range logs { l = append(l, v) } - alwaysLogs = &l + *alwaysLogs = l return nil } diff --git a/fab3/ethservice_test.go b/fab3/ethservice_test.go index ea5960f9..f981d1e9 100644 --- a/fab3/ethservice_test.go +++ b/fab3/ethservice_test.go @@ -1341,6 +1341,11 @@ var _ = Describe("Ethservice", func() { Describe("Filtering", func() { Context("NewFilter & UninstallFilter", func() { + BeforeEach(func() { + By("setting the legder up to have one block") + mockLedgerClient.QueryInfoReturns(&fab.BlockchainInfoResponse{BCI: &common.BlockchainInfo{Height: 1}}, nil) + }) + It("fails to find filters to uninstall when none are installed", func() { id := rand.Uint64() filter := types.FilterID{ID: id} @@ -1485,8 +1490,19 @@ var _ = Describe("Ethservice", func() { Context("getFilterLogs", func() { BeforeEach(func() { - By("setting the legder up to have one block") + By("setting the legder up to have some blocks") mockLedgerClient.QueryInfoReturns(&fab.BlockchainInfoResponse{BCI: &common.BlockchainInfo{Height: 1}}, nil) + + mockLedgerClient.QueryBlockStub = func(b uint64, _ ...ledger.RequestOption) (*common.Block, error) { + logger.Debug("mockblock", b) + if b == 0 { + return GetSampleBlock(0), nil + } else if b == 1 { + return GetSampleBlock(1), nil + } else { + return nil, fmt.Errorf("no block available for block number %d", b) + } + } }) It("errors on asking for a newBlock filter", func() { @@ -1503,28 +1519,52 @@ var _ = Describe("Ethservice", func() { }) It("gets logs the same way as GetLogs", func() { - var logsArgs *types.GetLogsArgs = &types.GetLogsArgs{} + var logsArgs *types.GetLogsArgs = &types.GetLogsArgs{FromBlock: "0"} var reply string - By("creating the filter with default args") + By("creating the filter with args") Expect(ethservice.NewFilter(&http.Request{}, logsArgs, &reply)).ToNot(HaveOccurred()) id, err := strconv.ParseUint(reply, 0, 16) Expect(err).ToNot(HaveOccurred()) + By("running the previously programmed filter") + filter := types.FilterID{ID: id} + var ret []interface{} + Expect(ethservice.GetFilterLogs(&http.Request{}, &filter, &ret)).ToNot(HaveOccurred()) + Expect(len(ret)).To(Equal(2)) + By("having new blocks show up") - mockLedgerClient.QueryBlockReturns(GetSampleBlock(0), nil) + mockLedgerClient.QueryInfoReturns(&fab.BlockchainInfoResponse{BCI: &common.BlockchainInfo{Height: 2}}, nil) By("running the previously programmed filter") + Expect(ethservice.GetFilterLogs(&http.Request{}, &filter, &ret)).ToNot(HaveOccurred()) + Expect(len(ret)).To(Equal(4), "should have more blocks than before") + }) + + It("creates a log filter, gets no logs, updates the ledger, gets logs, gets no logs", func() { + var logsArgs *types.GetLogsArgs = &types.GetLogsArgs{} + var reply string + + By("creating the filter with default args") + Expect(ethservice.NewFilter(&http.Request{}, logsArgs, &reply)).ToNot(HaveOccurred()) + id, err := strconv.ParseUint(reply, 0, 16) + Expect(err).ToNot(HaveOccurred()) + + By("not getting any logs without an update") filter := types.FilterID{ID: id} var ret []interface{} - Expect(ethservice.GetFilterLogs(&http.Request{}, &filter, &ret)).ToNot(HaveOccurred()) + Expect(ethservice.GetFilterChanges(&http.Request{}, &filter, &ret)).ToNot(HaveOccurred()) + Expect(len(ret)).To(Equal(0)) - By("uninstalling it to complete the lifecycle") - var valid bool - Expect(ethservice.UninstallFilter(&http.Request{}, &filter, &valid)).ToNot(HaveOccurred()) - Expect(valid).To(BeTrue()) + By("having new block show up") + mockLedgerClient.QueryInfoReturns(&fab.BlockchainInfoResponse{BCI: &common.BlockchainInfo{Height: 2}}, nil) + + By("getting only the logs in the new block") + Expect(ethservice.GetFilterChanges(&http.Request{}, &filter, &ret)).ToNot(HaveOccurred()) + Expect(len(ret)).To(Equal(2)) }) }) + }) Describe("GetTransactionCount", func() { diff --git a/fab3/filters.go b/fab3/filters.go index 94e6b187..fda483b4 100644 --- a/fab3/filters.go +++ b/fab3/filters.go @@ -33,24 +33,28 @@ func (f *logsFilter) LastAccessTime() time.Time { func (f *logsFilter) Filter(s *ethService) ([]interface{}, error) { s.logger.Debug("lastblockseen before filtering", f.latestBlockSeen) - blockNumber, err := s.parseBlockNum("latest") + currentLatestBlockSeen, err := s.parseBlockNum("latest") if err != nil { return nil, err } - s.logger.Debug("latest blockseen", blockNumber) + s.logger.Debug("latest blockseen", currentLatestBlockSeen) - var logs []types.Log - err = s.GetLogs(nil, f.logArgs, &logs) - if err != nil { - return nil, errors.Wrap(err, "GetLogs call failed") - } - l := make([]interface{}, 0, len(logs)) - for _, v := range logs { - l = append(l, v) + var l []interface{} + if f.latestBlockSeen < currentLatestBlockSeen { + var logs []types.Log + err = s.GetLogs(nil, f.logArgs, &logs) + if err != nil { + return nil, errors.Wrap(err, "GetLogs call failed") + } + l = make([]interface{}, 0, len(logs)) + for _, v := range logs { + l = append(l, v) + } } // update the filter f.lastAccessTime = time.Now() - f.logArgs.FromBlock = "0x" + strconv.FormatUint(blockNumber, 16) + f.logArgs.FromBlock = strconv.FormatUint(currentLatestBlockSeen+1, 16) + s.logger.Debug("returning %d logs", len(l)) return l, nil }