diff --git a/CHANGELOG.md b/CHANGELOG.md index aa0bfc0e1..72ceb2140 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,6 +17,8 @@ Versioning](http://semver.org/spec/v2.0.0.html) except to the first release. - Implemented stringer methods for pool.Role (#405). ### Changed +- More informative request canceling: log the probable reason for unexpected request ID + and add request ID info to context done error message (#407). ### Fixed diff --git a/connection.go b/connection.go index 53e6b874c..7c8e1294d 100644 --- a/connection.go +++ b/connection.go @@ -100,7 +100,8 @@ func (d defaultLogger) Report(event ConnLogKind, conn *Connection, v ...interfac conn.Addr(), err) case LogUnexpectedResultId: header := v[0].(Header) - log.Printf("tarantool: connection %s got unexpected resultId (%d) in response", + log.Printf("tarantool: connection %s got unexpected request ID (%d) in response "+ + "(probably cancelled request)", conn.Addr(), header.RequestId) case LogWatchEventReadFailed: err := v[0].(error) @@ -940,7 +941,7 @@ func (conn *Connection) newFuture(req Request) (fut *Future) { if ctx != nil { select { case <-ctx.Done(): - fut.SetError(fmt.Errorf("context is done")) + fut.SetError(fmt.Errorf("context is done (request ID %d)", fut.requestId)) shard.rmut.Unlock() return default: @@ -982,7 +983,7 @@ func (conn *Connection) contextWatchdog(fut *Future, ctx context.Context) { case <-fut.done: return default: - conn.cancelFuture(fut, fmt.Errorf("context is done")) + conn.cancelFuture(fut, fmt.Errorf("context is done (request ID %d)", fut.requestId)) } } @@ -1008,7 +1009,7 @@ func (conn *Connection) send(req Request, streamId uint64) *Future { if req.Ctx() != nil { select { case <-req.Ctx().Done(): - conn.cancelFuture(fut, fmt.Errorf("context is done")) + conn.cancelFuture(fut, fmt.Errorf("context is done (request ID %d)", fut.requestId)) return fut default: } diff --git a/example_test.go b/example_test.go index ec07b657b..d4480cea4 100644 --- a/example_test.go +++ b/example_test.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "net" + "regexp" "time" "github.com/tarantool/go-iproto" @@ -163,10 +164,10 @@ func ExamplePingRequest_Context() { // Ping a Tarantool instance to check connection. data, err := conn.Do(req).Get() fmt.Println("Ping Resp data", data) - fmt.Println("Ping Error", err) + fmt.Println("Ping Error", regexp.MustCompile("[0-9]+").ReplaceAllString(err.Error(), "N")) // Output: // Ping Resp data [] - // Ping Error context is done + // Ping Error context is done (request ID N) } func ExampleSelectRequest() { diff --git a/tarantool_test.go b/tarantool_test.go index 03b786f33..98f04a045 100644 --- a/tarantool_test.go +++ b/tarantool_test.go @@ -11,6 +11,7 @@ import ( "os/exec" "path/filepath" "reflect" + "regexp" "runtime" "strings" "sync" @@ -47,6 +48,8 @@ type Member struct { Val uint } +var contextDoneErrRegexp = regexp.MustCompile(`^context is done \(request ID [0-9]+\)$`) + func (m *Member) EncodeMsgpack(e *msgpack.Encoder) error { if err := e.EncodeArrayLen(2); err != nil { return err @@ -2731,7 +2734,7 @@ func TestClientRequestObjectsWithPassedCanceledContext(t *testing.T) { req := NewPingRequest().Context(ctx) cancel() resp, err := conn.Do(req).Get() - if err.Error() != "context is done" { + if !contextDoneErrRegexp.Match([]byte(err.Error())) { t.Fatalf("Failed to catch an error from done context") } if resp != nil { @@ -2802,7 +2805,7 @@ func TestClientRequestObjectsWithContext(t *testing.T) { if err == nil { t.Fatalf("caught nil error") } - if err.Error() != "context is done" { + if !contextDoneErrRegexp.Match([]byte(err.Error())) { t.Fatalf("wrong error caught: %v", err) } } @@ -3295,7 +3298,7 @@ func TestClientIdRequestObjectWithPassedCanceledContext(t *testing.T) { resp, err := conn.Do(req).Get() require.Nilf(t, resp, "Response is empty") require.NotNilf(t, err, "Error is not empty") - require.Equal(t, err.Error(), "context is done") + require.Regexp(t, contextDoneErrRegexp, err.Error()) } func TestConnectionProtocolInfoUnsupported(t *testing.T) {