From 43b9f5cb40f90491e137ce574c2bb72cc9633b45 Mon Sep 17 00:00:00 2001
From: Adolfo Builes <builes.adolfo@gmail.com>
Date: Tue, 10 Mar 2020 12:06:55 -0500
Subject: [PATCH] services/horizon: Ignore db.ErrCanceled and ctx.Canceled
 returned by verifyState. (#2366)

* Ignore db.ErrCanceled and ctx.Canceled returned by verifyState

If the system is shutdown during state verification, there is a
warning in the log showing

```
WARN[2020-02-04T18:14:19.987+01:00] State verification errored                    err="addAccountsToStateVerifier failed: Error running history.Q.GetAccountsByIDs: select failed: context canceled" pid=99452 service=expingest
```

If the system is being shutdown gracefully which is the case when we
get this errors, then we shouldn't log an error.

Fix #2224

* Add isCancelledError.

* Use isCancelledError in runStateMachine.

* Simplify isCancelledError.
---
 services/horizon/internal/expingest/main.go   | 15 ++--
 .../horizon/internal/expingest/main_test.go   | 68 +++++++++++++++++++
 2 files changed, 79 insertions(+), 4 deletions(-)

diff --git a/services/horizon/internal/expingest/main.go b/services/horizon/internal/expingest/main.go
index cb4993da39..8ba7ecb2d2 100644
--- a/services/horizon/internal/expingest/main.go
+++ b/services/horizon/internal/expingest/main.go
@@ -272,9 +272,7 @@ func (s *System) runStateMachine(cur stateMachineNode) error {
 		}
 
 		next, err := cur.run(s)
-		if cause := errors.Cause(err); cause != nil &&
-			cause != context.Canceled &&
-			cause != db.ErrCancelled {
+		if err != nil && !isCancelledError(err) {
 			log.WithFields(logpkg.F{
 				"error":         err,
 				"current_state": cur,
@@ -347,7 +345,7 @@ func (s *System) loadOffersIntoMemory(sequence uint32) error {
 
 func (s *System) maybeVerifyState(lastIngestedLedger uint32) {
 	stateInvalid, err := s.historyQ.GetExpStateInvalid()
-	if err != nil {
+	if err != nil && !isCancelledError(err) {
 		log.WithField("err", err).Error("Error getting state invalid value")
 	}
 
@@ -361,6 +359,10 @@ func (s *System) maybeVerifyState(lastIngestedLedger uint32) {
 
 			err := s.verifyState(graphOffersMap, true)
 			if err != nil {
+				if isCancelledError(err) {
+					return
+				}
+
 				errorCount := s.incrementStateVerificationErrors()
 				switch errors.Cause(err).(type) {
 				case ingesterrors.StateError:
@@ -429,3 +431,8 @@ func markStateInvalid(historyQ history.IngestionQ, err error) {
 		log.WithField("err", err).Error(updateExpStateInvalidErrMsg)
 	}
 }
+
+func isCancelledError(err error) bool {
+	cause := errors.Cause(err)
+	return cause == context.Canceled || cause == db.ErrCancelled
+}
diff --git a/services/horizon/internal/expingest/main_test.go b/services/horizon/internal/expingest/main_test.go
index c0e7c50241..8a22106a55 100644
--- a/services/horizon/internal/expingest/main_test.go
+++ b/services/horizon/internal/expingest/main_test.go
@@ -1,6 +1,7 @@
 package expingest
 
 import (
+	"bytes"
 	"context"
 	"database/sql"
 	"testing"
@@ -11,6 +12,7 @@ import (
 	"github.com/stellar/go/services/horizon/internal/db2/history"
 	"github.com/stellar/go/support/db"
 	"github.com/stellar/go/support/errors"
+	logpkg "github.com/stellar/go/support/log"
 	"github.com/stellar/go/xdr"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -165,6 +167,72 @@ func TestStateMachineRunReturnsErrorWhenNextStateIsShutdownWithError(t *testing.
 	assert.EqualError(t, err, "invalid range: [0, 0]")
 }
 
+func TestMaybeVerifyStateGetExpStateInvalidDBErrCancelOrContextCanceled(t *testing.T) {
+	historyQ := &mockDBQ{}
+	system := &System{
+		historyQ: historyQ,
+		ctx:      context.Background(),
+	}
+
+	var out bytes.Buffer
+	logger := logpkg.New()
+	logger.Logger.Out = &out
+	done := logger.StartTest(logpkg.InfoLevel)
+
+	oldLogger := log
+	log = logger
+	defer func() { log = oldLogger }()
+
+	historyQ.On("GetExpStateInvalid").Return(false, db.ErrCancelled).Once()
+	system.maybeVerifyState(0)
+
+	historyQ.On("GetExpStateInvalid").Return(false, context.Canceled).Once()
+	system.maybeVerifyState(0)
+
+	logged := done()
+	assert.Len(t, logged, 0)
+	historyQ.AssertExpectations(t)
+}
+func TestMaybeVerifyInternalDBErrCancelOrContextCanceled(t *testing.T) {
+	historyQ := &mockDBQ{}
+	graph := &mockOrderBookGraph{}
+	system := &System{
+		historyQ: historyQ,
+		ctx:      context.Background(),
+		graph:    graph,
+	}
+
+	var out bytes.Buffer
+	logger := logpkg.New()
+	logger.Logger.Out = &out
+	done := logger.StartTest(logpkg.InfoLevel)
+
+	oldLogger := log
+	log = logger
+	defer func() { log = oldLogger }()
+
+	graph.On("OffersMap").Return(map[xdr.Int64]xdr.OfferEntry{}).Twice()
+	historyQ.On("GetExpStateInvalid").Return(false, nil).Twice()
+	historyQ.On("Rollback").Return(nil).Twice()
+	historyQ.On("CloneIngestionQ").Return(historyQ).Twice()
+
+	historyQ.On("BeginTx", mock.Anything).Return(db.ErrCancelled).Once()
+	system.maybeVerifyState(63)
+	system.wg.Wait()
+
+	historyQ.On("BeginTx", mock.Anything).Return(context.Canceled).Once()
+	system.maybeVerifyState(63)
+	system.wg.Wait()
+
+	logged := done()
+
+	// it logs "State verification finished" twice, but no errors
+	assert.Len(t, logged, 2)
+
+	graph.AssertExpectations(t)
+	historyQ.AssertExpectations(t)
+}
+
 type mockDBQ struct {
 	mock.Mock