Get SQL Server Messages / PRINT command

[infogulch]

SQL Server supports the PRINT command which prints out a string. This is then available to the client, e.g. in SSMS it appears in the Messages tab.

Does the driver offer any way to access these?

[kardianos]

Right now, not that I'm aware of.

However, this is something I would personally like to enable in the future.

[infogulch]

Yes this would be nice to have.

I'm not very familiar with SQL Server internals. Do you know of any resources that would help someone implement this feature?

I found a StackOverflow answer that roughly describes how messages are transmitted, and apparently in .NET you're supposed to create a SqlInfoMessageEventHandler Delegate to handle the InfoMessage event of a SqlConnection. These don't help much to implement it yourself though.

[kardianos]

Oh, the driver already receives these messages. It is more of a question of database/sql API and how to expose them then anything.

[infogulch]

Ah, got it. So we need a proposal for another extension to database/sql. Does the raw driver expose an interface to access them now that such a proposal could build off of?

Edit: it looks like INFO messages are parsed in token.go#L590, and the answer to the above question is: no. :)

[jackielii]

I use the "log=63" in the connection string to print out the messages, not sure it's what you want?

[kardianos]

Please see the proposal on issue golang/go#19055 and the proposed CL https://golang.org/cl/39355 . This would allow dequeuing messages / print commands.

Please comment as the the suitability of this API.

[infogulch]

This looks great thanks for linking it.

[joetaber]

@kardianos I don't know how I decided to revisit this out of the blue the same minute you updated issue 19055, seems like quite a coincidence.

You say "I think this can be solved with messages.go if a driver supports it." Could you describe or show how this might look to the user?

[kardianos]

retmsg := &sqlexp.ReturnMessage{}
rows, err := db.QueryContext(ctx, "PRINT 'hi'; select * from Account; PRINT hello';", retmsg)
if err != nil {
    return err
}
defer rows.Close()

switch msg := retmsg.Message().(type) {
case sqlexp.MsgNotice:
    fmt.Println(msg.Message)
case sqlexp.MsgNextResultSet:
    if !rows.NextResultSet() {
        return
    }
case sqlexp.MsgNext:
    for rows.Next() {
        rows.Scan(...)
    }
}

The retmsg argument won't get passed to the query as it will be removed by the driver when checking the arguments by returning a special error message.

[shueybubbles]

@kardianos is there any effort underway to add the message support to go-mssqldb? If not I can take a stab at it to support my own project, as I don't really want to just inject a logger. The current logging code in the driver doesn't print the server provided messages anyway.

[kardianos]

@shueybubbles That would be great. It would need to be at the command level ideally anyway. If you wanted to stream messages, prior to receiving a result, you may be able to get away with smuggling in a messager interface through the context. Unfortunately, due to the design of database/sql, it makes retrieving messages inline with results difficult.

So yes, please do try

[shueybubbles]

To summarize - I will try the model described in @kardianos 's earlier comment based on the sqlexp interfaces as a starter. Once that's shown to work I would look at ways to stream the messages, perhaps through the ctx.

[tc-hib]

The current logging code in the driver doesn't print the server provided messages anyway.

What are those messages? I only know the INFO/ERROR messages, which already are in the logs.

Once that's shown to work I would look at ways to stream the messages, perhaps through the ctx.

I don't understand this part, as there's sqlexp.MsgNotice already.
By calling ReturnMessage.NextMessage() in a loop, aren't we already streaming messages and result sets?

[shueybubbles]

I'm looking to get the same messages for envchange (which may also come via the info/error channel) that sqlcmd shows:

1> use tempdb
2> go
Changed database context to 'tempdb'.
1> set language 'French'
2> go
Le paramètre de langue est passé à Français.

I don't see such messages in the test logs, ie when running go test -v -run ^TestSetLanguage$ . Do the tests not log the same thing you mean by "already in the logs" ?

[tc-hib]

Oh, I see, thanks.
These messages are missing because they're not enabled in the login message.
In prepareLogin, if you add OptionFlags1: 0xA0 you should see them.

[tc-hib]

There's another point I'd like to clarify: what should we do when we receive a non-fatal error? (severity 11 to 16)
Returning it along with a non-nil sql.Rows? Not returning it as long as it has been handled thanks to sqlexp.ReturnMessage?

For example:

RAISERROR ('Something went wrong, but please have a look at the following result set anyway', 11, 1)
SELECT 42

This currently only returns an error, while the server wants to send us a result set.

In the following case, the error is returned through sql.Rows.Err() and NextResultSet returns false.

SELECT 41
RAISERROR ('Something went wrong, but please have a look at the following result set anyway', 11, 1)
SELECT 42

---

On a side note, I've had a look at how the .Net client handles info messages: it simply has a callback (a delegate). That seems similar to the simplistic implementation I've tried there: https://github.com/denisenkom/go-mssqldb/compare/master...tc-hib:pr-message-handler?expand=1

[shueybubbles]

I'm fairly sure the driver should return both result sets and the error in between. I'm trying to replicate sqlcmd behavior for the most part, and that's what we get.

I think database changes etc are communicated as errors too, like error 5701 for changed database context. Maybe that's why the driver currently turns them off.

Which brings up a new question - should the new behavior be opt-in? I'd expect so, for apps that aren't using the message loop would not want error 5701 breaking them

[tc-hib]

I think database changes etc are communicated as errors too, like error 5701 for changed database context. Maybe that's why the driver currently turns them off.

No, these are INFO tokens, with error severity lower than 11.
I think it simply isn't enabled because nobody asked for it.
I think it should be optional, through the connection string.

[shueybubbles]

I think your callback model looks reasonable. I think it's kinda clunky to have to put it on every command though, when it would be scoped per connection for most apps. Would it be reasonable to also let an app provide the callback through the Connector? The per-Execute call could override the one in the Connector.

[tc-hib]

I wouldn't mind as long as I can still define it per command.
This is important to me, as I want to develop a service that forwards these messages to the front end.
And many queries won't need the callback at all.
To me, long batches with messages are more of a marginal case.

[shueybubbles]

@kardianos do you expect these messages can be sent directly from tokenProcessor or will tokenProcessor just add more token types to the channel and then the callers of nextToken will send messages accordingly?

For example, currently processQueryResponse doesn't return at all until it gets a []columnStruct:

				switch token := tok.(type) {
				// By ignoring DONE token we effectively
				// skip empty result-sets.
				// This improves results in queries like that:
				// set nocount on; select 1
				// see TestIgnoreEmptyResults test
				//case doneStruct:
				//break loop
				case []columnStruct:
					cols = token
					break loop
				case doneStruct:
					if token.isError() {
						// need to cleanup cancellable context
						cancel()
						return nil, s.c.checkBadConn(token.getError(), false)
					}
				case ReturnStatus:
					if reader.outs.returnStatus != nil {
						*reader.outs.returnStatus = token
					}
				case Error:
					
				}
			}

We definitely want to receive messages for print/insert/use etc as quickly as possible. I think there are several things to change about this particular method:

1. processQueryResponse needs to pass along the *sqlexp.ReturnMessage to startReading, either by adding it to s.c.sess or by a new parameter
2. the case doneStruct will have to inspect the error and not cancel or return it if it is an mssql.Error, or tokenProcessor will not add such errors to the doneStruct if the caller provided a ReturnMessage . A similar change will apply in Rows.Next()
3. tokenProcessor will queue MsgNotice and MsgError appropriately from here:

		case tokenError:
			err := parseError72(sess.buf)
			if sess.logFlags&logDebug != 0 {
				sess.log.Printf("got ERROR %d %s", err.Number, err.Message)
			}
			errs = append(errs, err)
			if sess.logFlags&logErrors != 0 {
				sess.log.Println(err.Message)
			}
		case tokenInfo:
			info := parseInfo(sess.buf)
			if sess.logFlags&logDebug != 0 {
				sess.log.Printf("got INFO %d %s", info.Number, info.Message)
			}
			if sess.logFlags&logMessages != 0 {
				sess.log.Println(info.Message)
			}

4. I think MsgNext and MsgNextResultSet have to be managed at the mssql level, not by tokenProcessor. Eg, processQueryResponse will send MsgNext just before it returns. Rows.Next would post MsgNextResultSet after getting a []columnStruct or after getting a doneStruct indicating no more data is coming. Rows.NextResultSet would post MsgNext if rc.nextCols != nil.

[shueybubbles]

Hmm I think processQueryResponse has to return right away and leave all the actual processing to processSingleResponse in order to make this work the way it's intended. Otherwise the caller has to wait until at least one result set comes back before they'll process any messages in the loop after calling Query.

[shueybubbles]

Having spent a bit more time tinkering I think I need to pass the ctx to processSingleResponse and make it responsible for all the message posts. It will send MsgNextResultSet when it sees new columns and MsgNext when it gets rows. When it gets a doneStruct with doneMore not set it will also send MsgNextResultSet to signal the end. Stay tuned.

[shueybubbles]

I think this code in sql.go is going to be problematic: https://github.com/golang/go/blob/6e738868a7a943d7d4fd6bb1963e7f6d78111726/src/database/sql/sql.go#L2978

It closes the Rows object if HasNextResultSet returns false. With the message queue model, we don't want the
Rows.Next() call to consume all the tokens in the channel, otherwise the client won't be able to process any messages until either the entire query finishes running or a second result set is encountered. In other words, sql.go shouldn't expect Rows to know whether there's another result set coming after it finishes reading the current result set.

I suppose the worst problem could be that intermediate messages between select statements are delayed, as the app will be waiting on rows.Next() while the messages are being queued , but that queue could get big.

Unless there's something I'm missing, @tc-hib 's proposal to use a plain synchronous logger func looks like the most reliable way to get messages and print them in the order received. We're very limited by how much reliance core has on rows.Next() to do all the work.

[shueybubbles]

Would it make sense for Rows to accumulate the messages instead of relying on any kind of queue or callback? I am not certain what other options have been discussed in the past for the core model.
That would align more with the ODBC style where all the results/errors/messages for a batch are associated with a SQLHSTMT.
I think ODBC has the same issue with lag as well, since messages are only available after a call to SQLMoreResults returns, which would have accumulated data between the last result set and the next.

Whereas with the message queue model proposed in sqlexp, if messages are queued during Rows.Next, the application has to manage the association with the current result set itself. It would have to store row data it fetched, wait for all the MsgNotice values to arrive until it gets new MsgNext or MsgNextResultSet, then print the messages and row data. That's assuming the app wants to print the messages before the row data, which makes sense most of the time.

[tc-hib]

I can't have a look at the code now, as I'm on vacation. But, the more I think about it, the more I believe the callback function might be good enough after all.

But we really have to decide how to handle errors that don't break the batch.

We also have to decide if we want the callback function to receive other kinds of events, such as DONE with rowcount, or env changes.

[shueybubbles]

FWIW I can make this test pass. Obviously I need to write some more extensive tests and clean things up for any type of PR but it's a start.

func TestMessageQueue(t *testing.T) {
	conn := open(t)
	defer conn.Close()
	retmsg := &sqlexp.ReturnMessage{}
	latency, _ := getLatency(t)
	ctx, _ := context.WithTimeout(context.Background(), latency+200000*time.Millisecond)
	rows, err := conn.QueryContext(ctx, "PRINT 'msg1'; select 100 as c; PRINT 'msg2'", retmsg)
	if err != nil {
		t.Fatal(err.Error())
	}
	defer rows.Close()
	active := true

	msgs := []interface{}{
		sqlexp.MsgNotice{Message: "msg1"},
		sqlexp.MsgNext{},
		sqlexp.MsgRowsAffected{Count: 1},
		sqlexp.MsgNotice{Message: "msg2"},
		sqlexp.MsgNextResultSet{},
	}
	i := 0
	rsCount := 0
	for active {
		msg := retmsg.Message(ctx)
		if i >= len(msgs) {
			t.Fatalf("Got extra message:%+v", msg)
		}
		t.Log(reflect.TypeOf(msg))
		if reflect.TypeOf(msgs[i]) != reflect.TypeOf(msg) {
			t.Fatalf("Out of order or incorrect message at %d. Actual: %+v. Expected: %+v", i, reflect.TypeOf(msg), reflect.TypeOf(msgs[i]))
		}
		switch m := msg.(type) {
		case sqlexp.MsgNotice:
			t.Log(m.Message)
		case sqlexp.MsgNextResultSet:
			active = rows.NextResultSet()
			if active {
				t.Fatal("NextResultSet returned true")
			}
			rsCount++
		case sqlexp.MsgNext:
			if !rows.Next() {
				t.Fatal("rows.Next() returned false")
			}
			var c int
			err = rows.Scan(&c)
			if err != nil {
				t.Fatalf("rows.Scan() failed: %s", err.Error())
			}
			if c != 100 {
				t.Fatalf("query returned wrong value: %d", c)
			}
		}
		i++
	}
}

The crux of the change is to split out some of the token handling to Rows.Columns and to add requestDone field so HasNextResultSet can return false more quickly in the common case of a select being the only or last statement of a batch.

processSingleResponse notifies the client of a result set:

		case tokenColMetadata:
			columns = parseColMetadata72(sess.buf)
			ch <- columns

			if outs.msgq != nil {
				if !firstResult {
					sqlexp.ReturnMessageEnqueue(ctx, outs.msgq, sqlexp.MsgNextResultSet{})
				} else {
					sqlexp.ReturnMessageEnqueue(ctx, outs.msgq, sqlexp.MsgNext{})
				}
			}
			firstResult = false

Then sql.go calls Columns so we scan for the columns:

func (rc *Rows) Columns() (res []string) {
	// in the message queue model, we know a column slice is in the channel because
	// the client received sqlexp.MsgNext or sqlexp.MsgNextResultSet
	if rc.reader.outs.msgq != nil {
	scan:
		for {
			tok, err := rc.reader.nextToken()
			if err == nil {
				if tok == nil {
					return []string{}
				} else {
					switch tokdata := tok.(type) {
					case []columnStruct:
						rc.cols = tokdata
						break scan
					}
				}
			}
		}
	}
	res = make([]string, len(rc.cols))
	for i, col := range rc.cols {
		res[i] = col.ColName
	}
	return
}

Then the app calls Next so Next has to wait for the rows:

func (rc *Rows) Next(dest []driver.Value) error {
	if !rc.stmt.c.connectionGood {
		return driver.ErrBadConn
	}
	if rc.reader.outs.msgq != nil {
		for {
			tok, err := rc.reader.nextToken()
			if err == nil {
				if tok == nil {
					return io.EOF
				} else {
					switch tokdata := tok.(type) {
					case []interface{}:
						for i := range dest {
							dest[i] = tokdata[i]
						}
						return nil
					case doneStruct:
						if tokdata.Status&doneMore == 0 {
							rc.requestDone = true
						}
						if tokdata.isError() {
							e := rc.stmt.c.checkBadConn(tokdata.getError(), false)
							switch e.(type) {
							case Error:
								// Ignore non-fatal server errors
							default:
								return e
							}
						}
						return io.EOF
					case ReturnStatus:
						if rc.reader.outs.returnStatus != nil {
							*rc.reader.outs.returnStatus = tokdata
						}
					}
				}

			} else {
				return rc.stmt.c.checkBadConn(err, false)
			}
		}
	}
... otherwise old behavior

[shueybubbles]

I'm finding several benefits to this "nonblocking" implementation that should be applicable to the non-message-loop based model.

1. Today, rows.NextResultSet() does not successfully advance to the next record set in the stream unless the app has call rows.Next() for every row in the current record set. My messages implementation enables that scenario.
2. The messages implementation doesn't stop when it hits an mssql.Error, so it can see all result sets after an error.
3. Performance seems to improve as well, based on a benchmark I wrote that executes the same query with multiple result sets and processes it with the old way and the new way in separate sub-benchmarks.

My PR is going to approach the solution thusly:

1. First iteration will implement a new Rowsq struct that inherits from Rows and for which we implement the driver interfaces for Rows. processQueryResponse will return a *Rowsq when reader.outs.msgq is non-nil. This way we isolate the behavior differences completely in the new methods.
2. i will include Test and Benchmark functions showing the differences in functionality between the old and new models.
3. Once we have consensus on the correctness of the implementation, I'd like to try to re-implement the older approach using the new Rowsq implementation which will show that we don't need to have rows.Next() greedily consume the stream until it reaches a column set or EOF and that we continue processing the query even when we hit a non-terminal error. If I can't for some reason get all the tests passing with this implementation then I just won't commit it and push it.

[infogulch]

I believe this is resolved by #690 for users of sqlexp. Thanks!