api: more informative request canceling

Log the probable reason for unexpected requestId.
Add requestId info to context done error message.

Author: nurzhan-saktaganov

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
 

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:
 		}

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() {

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) {