Server Message Handler and SQLException Chaining

[goranschwarz]

This is a solution to issue #1299

ServerMessageHandler

You can use the message handler for the following

• "message feedback"
  • Display Server messages from a long running SQL Statement... Like RAISERROR ('Progress message...', 0, 1) WITH NOWAIT
  • Or Status messages from a running backup...
• "Universal" error logging
  • Your error-message handler can contain the logic for handling all error logging
• "Universal" error handling
  • Error-handling logic can be placed in your error-message handler, instead of being repeated throughout your application.
• Remapping of error-message severity (based on application requirements)
  • Your error-message handler can contain logic for recognizing specific error messages, and downgrading or upgrading their severity based on application considerations rather than the severity rating of the server.
  • For example, during a cleanup operation that deletes old "stuff", you might want to downgrade the severity of "bad things".
    However, you may want to upgrade the severity in other circumstances.
  • If you write a "SQL Query Tool" (like SSMS) you might not want the Errors to terminate current SQL Batch (throw SQLException), but instead "map" the errors as a "warning"...

SQLException Chaining

I also found out that Exceptions do not contains any "extra messages" that is produced by the SQL Server.
For example when creating a stored proc with several errors in it, you will only see the first problem...
So this just adds any "extra" Messages to the first SQLWarning by setNextException

[goranschwarz]

@microsoft-github-policy-service agree

[tkyc]

Thanks for the contribution. In case review gets a bit delayed, just to let you know PR is on our radar.

[goranschwarz]

Thanks for the update, it would be nice to have it in release 12.5.0, if possible ;)

[Jeffery-Wasty]

Hi @goranschwarz,

With our 12.5.0 release planned for today (Nov 16), that doesn't look likely. The next release to include these changes will likely be a version bump. It's unclear at this time when this would be released.

[Jeffery-Wasty]

Adding on to my previous comment. This PR will NOT be included for the January 31 GA release. We'll look into including it in one of the following stable releases after 12.6.0.

[goranschwarz]

This PR will NOT be included for the January 31 GA release.

Just out of curiosity, what's the reason:

• Code is not good enough
• We just don't have time to review and merge it
• Or something else

[Jeffery-Wasty]

Hi @goranschwarz,

In summary, your second point; there is not enough time.

In detail, because of what this PR changes, and its size, this necessitates a approach to testing and review, different than what we would typically use with smaller PRs. With release planned for January 31, this gives us 7 weeks until a code freeze, plenty of time, but the team is currently engaged with other, high profile items. Its unclear when we would be able to start testing and reviewing, and we wouldn't want to rush such a large enhancement. We'll try to get to this as soon as we can, we don't want a community-contributed PR to sit for an extended amount of time, but timing-wise, it doesn't look like this can make our 12.6.0 GA release.

[goranschwarz]

OK; That sounds fare!

Let me know if I can help in any way...

[lilgreenbird]

as mentioned above, this isn't going to make the GA release. I've put this into the backlog for now we will look at this again after the Jan release.

[tkyc]

Looks good in our internal pipelines. But, it looks like exception chaining isn't working for the scenario described in #2115. From debugging, it looks like the TDS stream is returning only one error message and so only one error message is set.

[goranschwarz]

I wanted to change as little as possible!
The code for Server Message Handler is just "hooking into" the current code, without changing the flow of how things are processed (TDS Streaming wise)

@tkyc Regarding SQLException chaining

• The code in the PR will only work for commands that returns several Errors in one SQL Command
  (and nested stored procedure calls is not "one" command if you look at the TDS Stream, and how we are currently processing it.)

To solve #2115 (several error messages in nested procedures), or multiple TDS_ERR in the TDS Stream
We need to do a lot more changes (below is possibly why)

• SQLExceptions are thrown early, when reading the TDS Stream
• and on stmnt.close() we read the remaining TDS Stream, which contains those Error Messages (but at that time we have already thrown the SQLException)
  So we need to read out more of the TDS Stream before SQLExceptions are throws...
  And to do that I think a lot of changes and tests are needed

What I'm trying to accomplish with the "Server Message Handler", is to be able to downgrade a SQLException to a SQLWarning
(hence trying to be more like SSMS, meaning: continue to read the Data/Messages without aborting (by an SQLException) until the SQL Batch is complete)

I did some test of the "nested" procedure errors (with some debug printing in the MS JDBC Driver)

This to trace what TDS Stream Tokens that was received (hence where did the Error messages go...)

Simple stmnt.executeUpdate(sql) code
Note: I also tested with stmnt.executeQuery(sql) and stmnt.execute(sql)
And they shows the "same" output as below

Test code (I can post the full if you want to):

			System.out.println("");
			System.out.println("#####################################################");
			System.out.println("### executeUpdate('" + sql + "')");
			System.out.println("#####################################################");
			Statement stmnt = conn.createStatement();
			try //(Statement stmnt = conn.createStatement())
			{
				stmnt.executeUpdate(sql);

				SQLWarning ex = stmnt.getWarnings();
				while(ex != null)
				{
					System.out.println(">>> WARNING: Msg=" + ex.getErrorCode() + ", xxx=" + ex.getSQLState() + ", Text=|" + ex.getMessage() + "|.");
					ex = ex.getNextWarning();
				}
			}
			catch (SQLException ex)
			{
				while(ex != null)
				{
					System.out.println(">>> EXCEPTION: Msg=" + ex.getErrorCode() + ", xxx=" + ex.getSQLState() + ", Text=|" + ex.getMessage() + "|.");
					ex = ex.getNextException();
				}

				ex = stmnt.getWarnings();
				while(ex != null)
				{
					System.out.println(">>> WARNING: Msg=" + ex.getErrorCode() + ", xxx=" + ex.getSQLState() + ", Text=|" + ex.getMessage() + "|.");
					ex = ex.getNextException();
				}
			}
			finally {
				System.out.println("### stmnt.close()");
				stmnt.close();
			}

And it's output

#####################################################
### executeUpdate('exec p1 @doSelect = 0')
#####################################################
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=170, getTokenName=TDS_ERR (0xAA)
     - AT: TDSTokenHandler.addDatabaseError(): logContext='getNextResult', databaseError=P2 - inner EXCEPTION text. sev=16
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = true <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< parsing will be set to FALSE in the TDS-PARSE() loop.
>>> EXCEPTION: Msg=50000, xxx=S0001, Text=|P2 - inner EXCEPTION text. sev=16|.
### stmnt.close()
  -- TDS PARSE(): tdsTokenType=171, getTokenName=TDS_MSG (0xAB)
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=170, getTokenName=TDS_ERR (0xAA)
     - AT: TDSTokenHandler.addDatabaseError(): logContext='getNextResult', databaseError=P1 - P2 raised an EXCEPTION. sev=16
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = true <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< parsing will be set to FALSE in the TDS-PARSE() loop.
  -- TDS PARSE(): tdsTokenType=171, getTokenName=TDS_MSG (0xAB)
  -- TDS PARSE(): tdsTokenType=255, getTokenName=TDS_DONEINPROC (0xFF)
     - AT: NextResult.onDone(): doneToken.isError() = false
  -- TDS PARSE(): tdsTokenType=121, getTokenName=TDS_RET_STAT (0x79)
  -- TDS PARSE(): tdsTokenType=254, getTokenName=TDS_DONEPROC (0xFE)
  -- TDS PARSE(): tdsTokenType=-1, getTokenName=unknown token (0xFFFFFFFF)

Extra info trying to "fix" that we Read more TDS Tokens before Throwing SQLException

Yes I did some test, which initially looked good but I "scrapped" them pretty quickly
The change was to comment out the below line at: SQLServerStatement.java, approx row: 1587

                // If the current command (whatever it was) produced an error then stop parsing and propagate it up.
                // In this case, the command is likely to be a RAISERROR, but it could be anything.
System.out.println("     - AT: NextResult.onDone(): doneToken.isError() = " + doneToken.isError() + (doneToken.isError() ? " <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< parsing will be set to FALSE in the TDS-PARSE() loop." : ""));
//                if (doneToken.isError())
//                    return false;

                // In all other cases, keep parsing
                return true;

Then it worked...
BUT When mixing a couple of SELECT 'some text' in the procedures it didn't work anymore...

For completeness here are the Stored procedure code

drop procedure p2
go
drop procedure p1
go
create procedure p2 (@doSelect int = 0)
as
begin
	if (@doSelect > 0)
		select 'SELECT at -- P2 - inner execution'

	raiserror('P2 - inner EXCEPTION text. sev=16', 16, 1) with nowait
	raiserror('P2 - inner WARNING text. sev=10', 10, 1) with nowait
--	return 0
	return 1
end
go
create procedure p1 (@doSelect int = 0)
as
begin
	declare @rc int

	if (@doSelect > 0)
		select 'SELECT at -- P1 - inner execution -- BEFORE'

	exec @rc=p2 @doSelect

	if (@doSelect > 0)
		select 'SELECT at -- P1 - inner execution -- AFTER'

	if (@rc != 0)
	begin
		raiserror('P1 - P2 raised an EXCEPTION. sev=16', 16, 1) with nowait
		raiserror('P1 - P2 warning an WARNING. sev=10', 10, 1) with nowait
	end
end
go

For even more completeness here are a "path" of what I LOCALLY changed to get the DEBUG Prints

diff --git a/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java b/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
index b14f40e..ad0a17d 100644
--- a/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
+++ b/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerStatement.java
@@ -1583,6 +1583,7 @@
                 }
                 // If the current command (whatever it was) produced an error then stop parsing and propagate it up.
                 // In this case, the command is likely to be a RAISERROR, but it could be anything.
+System.out.println("     - AT: NextResult.onDone(): doneToken.isError() = " + doneToken.isError() + (doneToken.isError() ? " <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< parsing will be set to FALSE in the TDS-PARSE() loop." : ""));
                 if (doneToken.isError())
                     return false;
 
diff --git a/src/main/java/com/microsoft/sqlserver/jdbc/tdsparser.java b/src/main/java/com/microsoft/sqlserver/jdbc/tdsparser.java
index 1a79a43..4a9a03b 100644
--- a/src/main/java/com/microsoft/sqlserver/jdbc/tdsparser.java
+++ b/src/main/java/com/microsoft/sqlserver/jdbc/tdsparser.java
@@ -64,6 +64,7 @@
         boolean isFeatureExtAck = false;
         while (parsing) {
             int tdsTokenType = tdsReader.peekTokenType();
+System.out.println("  -- TDS PARSE(): tdsTokenType="+tdsTokenType+", getTokenName="+com.microsoft.sqlserver.jdbc.TDS.getTokenName(tdsTokenType));
             if (isLogging) {
                 logger.finest(tdsReader.toString() + ": " + tdsTokenHandler.logContext + ": Processing "
                         + ((-1 == tdsTokenType) ? "EOF" : TDS.getTokenName(tdsTokenType)));
@@ -142,6 +143,7 @@
                     throwUnexpectedTokenException(tdsReader, tdsTokenHandler.logContext);
                     break;
             }
+//System.out.println("  " + (parsing ? "  " : "<<") + "            : parsing == " + parsing + (parsing ? "" : " <<<<<<<<<<<<<<< BREAKING WHILE LOOP <<<<<<<<<<<<<<<"));
         }
 
         // if TDS_FEATURE_EXTENSION_ACK is not received verify if TDS_FEATURE_EXT_AE was sent
@@ -198,6 +200,8 @@
     }
 
     public void addDatabaseError(SQLServerError databaseError) {
+System.out.println("     - AT: TDSTokenHandler.addDatabaseError(): logContext='"+this.logContext+"', databaseError="+databaseError.getErrorMessage());
+//new Exception("databaseError="+databaseError.getErrorMessage()).printStackTrace();
         if (this.databaseError == null) {
             this.databaseError = databaseError;
         } else {
@@ -247,6 +251,7 @@
     boolean onDone(TDSReader tdsReader) throws SQLServerException {
         StreamDone doneToken = new StreamDone();
         doneToken.setFromTDS(tdsReader);
+System.out.println("     - AT tdsParser.onDone(): doneToken.isFinal()="+doneToken.isFinal());
         if (doneToken.isFinal()) {
             // Response is completely processed hence decrement unprocessed response count.
             tdsReader.getConnection().getSessionRecovery().decrementUnprocessedResponseCount();

hmmm... This become longer than initially intended :)
But I hope it made sense, and some clarity!

[lilgreenbird]

since we now have 2 of these, add comment on how they differ and how they are used

[goranschwarz]

done

[lilgreenbird]

using -1 seem a bit of a hack, can we just create diff overloaded helpers to handle diff scenarios instead

[goranschwarz]

Not 100% sure what you say here!
But I have:

• toSQLServerError()
  to be used if no changes to the 'errorNumber' and 'errorSeverity'
• toSQLServerError(int newErrorSeverity)
  to be used if only 'errorNumber' should be changed
• toSQLServerError(int newErrorSeverity, int newErrorNumber)
  to be used if you want to change both the 'errorNumber' and 'errorSeverity'

The first two methods just calls: toSQLServerError(int newErrorSeverity, int newErrorNumber)
So we don't have to duplicate the code...

Give me an example of how I should do it...

[lilgreenbird]

javadoc class description

[goranschwarz]

done

[lilgreenbird]

Please make sure to use the formatter on all files. I'm seeing a lot of spacing diffs when I pulled this branch.

Also, pls resolve conflicts

[lilgreenbird]

nitpick: since this is a public API, can you please use a full spelling instead

Suggested change

	ISQLServerMessage messageHandler(ISQLServerMessage srvErrorOrWarning);
	ISQLServerMessage messageHandler(ISQLServerMessage serverErrorOrWarning);

[goranschwarz]

done

[lilgreenbird]

why does the setter need to return anything? there is already a getter

[goranschwarz]

This is just convenience...
Meaning: not have to call getter if you want to save the previous installed handler...
Which may be used if you want to restore previous installed handler at a later point!

For example the java Properties.getProperty("someName") does the same thing!
https://docs.oracle.com/javase/8/docs/api/java/util/Properties.html#setProperty-java.lang.String-java.lang.String-

[lilgreenbird]

this overwrites any existing, maybe should check and log a message?

[goranschwarz]

Yes a setter usually overwrites previous values...
If you don't want to overwrite it, use the getter and check if you have one...

If you want: I can generate a log message (let me know the LogLevel)
But from my perspective, I would leave it as is

[codecov]

Codecov Report

Attention: Patch coverage is 60.00000% with 48 lines in your changes are missing coverage. Please review.

Project coverage is 50.00%. Comparing base (eae6d7b) to head (9c3fe8b).

❗ Current head 9c3fe8b differs from pull request most recent head 73c6ad7. Consider uploading reports for the commit 73c6ad7 to get more accurate results

Files	Patch %	Lines
...a/com/microsoft/sqlserver/jdbc/SQLServerError.java	32.14%	17 Missing and 2 partials ⚠️
...microsoft/sqlserver/jdbc/SQLServerInfoMessage.java	44.44%	14 Missing and 1 partial ⚠️
...m/microsoft/sqlserver/jdbc/SQLServerException.java	64.28%	5 Missing ⚠️
...m/microsoft/sqlserver/jdbc/SQLServerStatement.java	71.42%	2 Missing and 2 partials ⚠️
.../microsoft/sqlserver/jdbc/SQLServerConnection.java	83.33%	1 Missing and 1 partial ⚠️
...t/sqlserver/jdbc/SQLServerConnectionPoolProxy.java	50.00%	1 Missing ⚠️
...com/microsoft/sqlserver/jdbc/SQLServerWarning.java	83.33%	1 Missing ⚠️
...n/java/com/microsoft/sqlserver/jdbc/tdsparser.java	93.33%	0 Missing and 1 partial ⚠️

Additional details and impacted files

@@              Coverage Diff              @@
##               main    #2251       +/-   ##
=============================================
- Coverage     73.56%   50.00%   -23.56%     
+ Complexity     6079     3806     -2273     
=============================================
  Files           143      145        +2     
  Lines         33179    33279      +100     
  Branches       5631     5643       +12     
=============================================
- Hits          24407    16641     -7766     
- Misses         6255    14251     +7996     
+ Partials       2517     2387      -130     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[goranschwarz]

@lilgreenbird
Just to be sure: I guess you have seen my answers to your "review comments"?
But you are busy with other stuff...