Implement sqlexp Messages for Query/QueryContext

[shueybubbles]

This is a minimally invasive addition to address #221.
For existing callers, the only change is the log will include messages for language and database changes.
Apps that want to take advantage of https://github.com/golang-sql/sqlexp can now write a message loop to retrieve data sets, errors, and messages.

A sample loop might look like this:

        db := sql.OpenDB(connector)
	defer db.Close()
	retmsg := &sqlexp.ReturnMessage{}
	ctx := context.Background()
	rows, err := db.QueryContext(ctx, `select name from sys.tables
PRINT N'This is a message'
select 199
RAISERROR (N'Testing!' , 11, 1)
select 300
`, retmsg)
	if err != nil {
		log.Fatalf("QueryContext failed: %v", err)
	}
	active := true
	for active {
		msg := retmsg.Message(ctx)
		switch m := msg.(type) {
		case sqlexp.MsgNotice:
			fmt.Println(m.Message)
		case sqlexp.MsgNext:
			inresult := true
			for inresult {
				inresult = rows.Next()
                                if inresult {
  				    cols, err := rows.Columns()
				    if err != nil {
				  	    log.Fatalf("Columns failed: %v", err)
				    }
				    fmt.Println(cols)
				    var d interface{}
				    rows.Scan(&d)
				    fmt.Println(d)
				}
			}
		case sqlexp.MsgNextResultSet:
			active = rows.NextResultSet()
		case sqlexp.MsgError:
			fmt.Fprintln(os.Stderr, m.Error)
		case sqlexp.MsgRowsAffected:
			fmt.Println("Rows affected:", m.Count)
		}
	}

[shueybubbles]

What should we do if ReturnMessageEnqueue fails? Simply returning the error doesn't seem helpful as it won't be any kind of error the caller can reasonably handle, is it? We definitely wouldn't want to have data/sql retry it.
Should we just panic?

[shueybubbles]

I looked at why it would return an error and it seems like overkill for it return ctx.Err() because the app is going to get that error back from Message() anyway.

// Message is called by clients after Query to dequeue messages.
func (m *ReturnMessage) Message(ctx context.Context) RawMessage {
	select {
	case <-ctx.Done():
		return MsgNextResultSet{}
	case raw := <-m.queue:
		return raw
	}
}

// ReturnMessageEnqueue is called by the driver to enqueue the driver.
// Drivers should not call this until after it returns from Query.
func ReturnMessageEnqueue(ctx context.Context, m *ReturnMessage, raw RawMessage) error {
	select {
	case <-ctx.Done():
		return ctx.Err()
	case m.queue <- raw:
		return nil
	}
}

[shueybubbles]

let me write a test where the context times out and doesn't return any results. I am not sure what will happen :-) I should probably write the error to the channel.

[shueybubbles]

This is the basis of a test I think:

ctx := context.WithTimeout(context.Background(),  5000*time.Millisecond)
	retmsg := &sqlexp.ReturnMessage{}
	r, err := conn.QueryContext(ctx, `waitfor delay '00:00:15'; select 100`, retmsg)
	

With my current implementation the client won't ever see a sqlexp.MsgNext because it waits until it gets columns to send it. I think I can just post MsgNext as the first thing inside processSingleResponse

[shueybubbles]

then again, it seems the core data/sql code handles this already. This test passes if I don't do anything to handle errors from ReturnMessageEnqueue. The only message in the log is MsgNextResultSet

func TestTimeoutWithNoResults(t *testing.T) {
	conn := open(t)
	defer conn.Close()
	latency, _ := getLatency(t)
	ctx, _ := context.WithTimeout(context.Background(), latency+5000*time.Millisecond)
	retmsg := &sqlexp.ReturnMessage{}
	r, err := conn.QueryContext(ctx, `waitfor delay '00:00:15'; select 100`, retmsg)
	if err != nil {
		t.Fatal(err.Error())
	}
	defer r.Close()
	active := true
	for active {
		msg := retmsg.Message(ctx)
		t.Logf("Got a message: %s", reflect.TypeOf(msg))
		switch m := msg.(type) {
		case sqlexp.MsgNextResultSet:
			active = r.NextResultSet()
			if active {
				t.Fatal("NextResultSet returned true")
			}
		case sqlexp.MsgNext:
			if r.Next() {
				t.Fatal("Got a successful Next even though the query should have timed out")
			}
		case sqlexp.MsgRowsAffected:
			t.Fatalf("Got a MsgRowsAffected %d", m.Count)
		}
	}
	if r.Err() != context.DeadlineExceeded {
		t.Fatalf("Unexpected error: %v", r.Err())
	}

}

[shueybubbles]

this case seems to be somewhat problematic. Occasionally the new test or benchmark will fail because it only reads 3 result sets instead of 4. The common behavior in each of the failures is that the log has an extra DoneStruct with status = 32 indicating we went down this code path without reading the row tokens from the channel first.
Do you have any clues on what might causes ctx.Done() to fire here before we empty the channel? Should processSingleResponse not return right away when it gets a doneStruct with an even numbered status? I am going to add some logging locally to try to track this down.

[kardianos]

We probably need to look into removing the go routines happy reads (as a guess). denisenkom has a branch with that prototyped, though it needs cancellation and brought up to speed. But it might be something else, we should look into it.

[codecov]

Codecov Report

Merging #690 (4cc6bc3) into master (f6fd477) will increase coverage by 0.19%.
The diff coverage is 69.02%.

❗ Current head 4cc6bc3 differs from pull request most recent head fab6304. Consider uploading reports for the commit fab6304 to get more accurate results

@@            Coverage Diff             @@
##           master     #690      +/-   ##
==========================================
+ Coverage   70.96%   71.16%   +0.19%     
==========================================
  Files          24       24              
  Lines        5208     5386     +178     
==========================================
+ Hits         3696     3833     +137     
- Misses       1285     1305      +20     
- Partials      227      248      +21     

Impacted Files	Coverage Δ
mssql.go	87.75% <67.42%> (-4.03%)	⬇️
token.go	63.62% <70.21%> (+1.77%)	⬆️
mssql_go19.go	95.86% <100.00%> (+0.11%)	⬆️
tds.go	65.49% <100.00%> (+0.76%)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f6fd477...fab6304. Read the comment docs.

[fineol]

I think it would be better to select something that won't vary from system to system (and potentially even run to run). That would make the test more repeatable.

[shueybubbles]

I have a consumer application for this feature. See https://github.com/microsoft/go-sqlcmd/blob/c3cd43b19dd77c0fc6761b552c03e599b7e7b338/pkg/sqlcmd/sqlcmd.go#L452

[kardianos]

I just merged azure. If you could update?

[kardianos]

We probably need to look into removing the go routines happy reads (as a guess). denisenkom has a branch with that prototyped, though it needs cancellation and brought up to speed. But it might be something else, we should look into it.