Not catching results generated after PRINT or warning from stored procedures with NOCOUNT on

mdpenguin commented 1 year ago

If a statement in a stored procedure produces a record set then procedureMgr is not returning it in the results if the record set follows one of the following:

a PRINT statement
an ANSI warning
an error message with a severity level <= 10 (a warning rather than a halting error)

This can be replicated with this stored procedure:

CREATE PROCEDURE [dbo].[NullEliminated](@P1 TINYINT)
AS
BEGIN
    SET NOCOUNT ON;

    CREATE TABLE #Dummy (ID TINYINT);

    SELECT 'First query' 'FirstQuery';

    SELECT 'Second query' 'SecondQuery';

    PRINT 'That was second; now we do third';

    SELECT 'Third query' 'ThirdQuery';

    SELECT 'Fourth query' 'FourthQuery';

    SELECT 'Fifth query' 'FifthQuery';

    INSERT INTO #Dummy(ID)
    SELECT SUM(n) 'ID'
    FROM(VALUES(1),
               (NULL)) x(n);

    INSERT INTO #Dummy(ID)
    SELECT SUM(n) 'ID'
    FROM(VALUES(1),
               (NULL)) x(n);

    SELECT 'Sixth query' 'SixthQuery';

    SELECT 'Seventh query' 'SeventhQuery';

    RAISERROR('I am warning you!', 10, 1);

    SELECT 'Eighth query' 'EighthQuery';
END

Here is the JS I was using to run the procedure:

const sql = require("msnodesqlv8");

const connectionString = "Driver={ODBC Driver 17 for SQL Server};Server=YourServerHere;Database=YourDBHere;Trusted_Connection=yes;'";

sql.open(connectionString, function (err, conn) {
    var pm = conn.procedureMgr();
    pm.callproc('NullEliminated', [10], function (err, results, output) {
        console.log(results);
    });
});

And the results I get from that are:

[ { FirstQuery: 'First query' } ]
[]
[ { SecondQuery: 'Second query' } ]
[ { FourthQuery: 'Fourth query' } ]
[]
[ { FifthQuery: 'Fifth query' } ]
[]
[ { SeventhQuery: 'Seventh query' } ]

Note the following:

The third query fails to show after the PRINT statement
The sixth query fails to show after a couple of ANSI warnings about nulls in aggregate functions
The eighth query fails to show after a warning message is raised

After removing "SET NOCOUNT ON" from the stored procedure, all eight result sets are returned as seen below, though there are still some extra empty result sets included.

[ { FirstQuery: 'First query' } ]
[]
[ { SecondQuery: 'Second query' } ]
[ { ThirdQuery: 'Third query' } ]
[ { FourthQuery: 'Fourth query' } ]
[]
[]
[ { FifthQuery: 'Fifth query' } ]
[ { SixthQuery: 'Sixth query' } ]
[]
[ { SeventhQuery: 'Seventh query' } ]
[ { EighthQuery: 'Eighth query' } ]

TimelordUK commented 1 year ago

I am testing a fix for this - uing the promised based API with fix in place we see below. I am not sure at this point if any regression is introduced with change.

const spName = 'test_sp_missing'    

  const def2 = `alter PROCEDURE [dbo].[${spName}](@P1 TINYINT)
  AS
  BEGIN
      SET NOCOUNT ON;

      CREATE TABLE #Dummy (ID TINYINT);

      SELECT 'First query' 'FirstQuery';

      SELECT 'Second query' 'SecondQuery';

      PRINT 'That was second; now we do third';

      SELECT 'Third query' 'ThirdQuery';

      SELECT 'Fourth query' 'FourthQuery';

      SELECT 'Fifth query' 'FifthQuery';

      INSERT INTO #Dummy(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);

      INSERT INTO #Dummy(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);

      SELECT 'Sixth query' 'SixthQuery';

      SELECT 'Seventh query' 'SeventhQuery';

      RAISERROR('I am warning you!', 10, 1);

      SELECT 'Eighth query' 'EighthQuery';
  END
  `

    it('connection: call proc ensure no drop sets', async function handler () {
    await env.promisedCreate(spName, def2)
    const res = await env.theConnection.promises.callProc(spName, [10])
    expect(res.results.length).is.equal(8)

    expect(res.results[0][0].FirstQuery).is.equal('First query')
    expect(res.results[1][0].SecondQuery).is.equal('Second query')
    expect(res.results[2][0].ThirdQuery).is.equal('Third query')
    expect(res.results[3][0].FourthQuery).is.equal('Fourth query')
    expect(res.results[4][0].FifthQuery).is.equal('Fifth query')
    expect(res.results[5][0].SixthQuery).is.equal('Sixth query')
    expect(res.results[6][0].SeventhQuery).is.equal('Seventh query')
    expect(res.results[7][0].EighthQuery).is.equal('Eighth query')

    expect(res.info[0]).is.equal('That was second; now we do third')
    expect(res.info[1]).is.equal('Warning: Null value is eliminated by an aggregate or other SET operation.')
    expect(res.info[2]).is.equal('I am warning you!')

    console.log(JSON.stringify(res, null, 4))
  })

{
    "beginAt": "2023-02-08T21:01:05.249Z",
    "submittedAt": "2023-02-08T21:01:05.425Z",
    "endAt": "2023-02-08T21:01:05.455Z",
    "elapsed": 206,
    "first": [
        {
            "FirstQuery": "First query"
        }
    ],
    "firstMeta": [
        {
            "size": 11,
            "name": "FirstQuery",
            "nullable": false,
            "type": "text",
            "sqlType": "varchar"
        }
    ],
    "meta": [
        [
            {
                "size": 11,
                "name": "FirstQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 12,
                "name": "SecondQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 11,
                "name": "ThirdQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 12,
                "name": "FourthQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 11,
                "name": "FifthQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 11,
                "name": "SixthQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 13,
                "name": "SeventhQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ],
        [
            {
                "size": 12,
                "name": "EighthQuery",
                "nullable": false,
                "type": "text",
                "sqlType": "varchar"
            }
        ]
    ],
    "metaElapsed": [
        199,
        201,
        202,
        202,
        203,
        203,
        204,
        205
    ],
    "counts": [],
    "results": [
        [
            {
                "FirstQuery": "First query"
            }
        ],
        [
            {
                "SecondQuery": "Second query"
            }
        ],
        [
            {
                "ThirdQuery": "Third query"
            }
        ],
        [
            {
                "FourthQuery": "Fourth query"
            }
        ],
        [
            {
                "FifthQuery": "Fifth query"
            }
        ],
        [
            {
                "SixthQuery": "Sixth query"
            }
        ],
        [
            {
                "SeventhQuery": "Seventh query"
            }
        ],
        [
            {
                "EighthQuery": "Eighth query"
            }
        ]
    ],
    "output": [
        0
    ],
    "info": [
        "That was second; now we do third",
        "Warning: Null value is eliminated by an aggregate or other SET operation.",
        "I am warning you!"
    ],
    "errors": [],
    "options": {
        "timeoutMs": 0,
        "raw": false,
        "replaceEmptyColumnNames": false
    },
    "rows": 8,
    "row": null,
    "rowRate": 39.02439024390244,
    "sql": "{ ? = call test_sp_missing(@P1 = ?) }",
    "returns": 0
}

TimelordUK commented 1 year ago

what we now have on master goes a long way to improve matters - all results should be picked up. regarding the warning message i do not think this is directly related to this driver we rely on the cpp giving a success with info return code indicating a warning error message can be read- in example below we do get that and collect both messages

it('connection: call proc 2 inserts warnings with prints', async function handler () {
    const spName = 'test_sp_missing'
    const tableName = '#Dummy'

    const def2 = `alter PROCEDURE [dbo].[${spName}](@P1 TINYINT)
  AS
  BEGIN
      SET NOCOUNT ON;

      CREATE TABLE ${tableName} (ID TINYINT);

      PRINT 'insert 1';
      INSERT INTO ${tableName}(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);
      PRINT 'select 1';
      select * from ${tableName}; 

      PRINT 'insert 2';
      INSERT INTO ${tableName}(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);

      PRINT 'select 2';
      select * from ${tableName}; 
  END
  `
    const expectedInfo = [
      'Warning: Null value is eliminated by an aggregate or other SET operation.',
      'insert 1',
      'select 1',
      'Warning: Null value is eliminated by an aggregate or other SET operation.',
      'insert 2',
      'select 2'
    ]
    const expectedResults = [
      [
        {
          ID: 1
        }
      ],
      [
        {
          ID: 1
        },
        {
          ID: 1
        }
      ]
    ]
    const expectedMeta = [
      [
        {
          size: 3,
          name: 'ID',
          nullable: true,
          type: 'number',
          sqlType: 'tinyint'
        }
      ],
      [
        {
          size: 3,
          name: 'ID',
          nullable: true,
          type: 'number',
          sqlType: 'tinyint'
        }
      ]
    ]
    await env.promisedCreate(spName, def2)
    const res = await env.theConnection.promises.callProc(spName, [10])
    expect(res.results).is.deep.equal(expectedResults)
    expect(res.meta).is.deep.equal(expectedMeta)
    expect(res.info).is.deep.equal(expectedInfo)
    // console.log(JSON.stringify(res, null, 4))
  })

but with back to back and no print we do not raise the second warning

it('connection: call proc 2 null warnings', async function handler () {
    const spName = 'test_sp_missing'
    const tableName = '#Dummy'

    const def2 = `alter PROCEDURE [dbo].[${spName}](@P1 TINYINT)
  AS
  BEGIN
      SET NOCOUNT ON;

      CREATE TABLE ${tableName} (ID TINYINT);

      INSERT INTO ${tableName}(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);

      INSERT INTO ${tableName}(ID)
      SELECT SUM(n) 'ID'
      FROM(VALUES(1),
                 (NULL)) x(n);

      select * from ${tableName}; 
  END
  `

    await env.promisedCreate(spName, def2)
    const expectedMeta = [
      [
        {
          size: 3,
          name: 'ID',
          nullable: true,
          type: 'number',
          sqlType: 'tinyint'
        }
      ]
    ]
    const expectedResults = [
      [
        {
          ID: 1
        },
        {
          ID: 1
        }
      ]
    ]
    const expectedInfo = [
      'Warning: Null value is eliminated by an aggregate or other SET operation.'
    ]
    const res = await env.theConnection.promises.callProc(spName, [])
    expect(res.meta).is.deep.equal(expectedMeta)
    expect(res.results).is.deep.equal(expectedResults)
    expect(res.info).is.deep.equal(expectedInfo)
  })

in all cases we do seem to pick up results correctly. This will be released shortly, I do not think we can do anything without the return code raised by ODBC as mentioned above which we do not get in above case

mdpenguin commented 1 year ago

I can confirm that https://github.com/TimelordUK/node-sqlserver-v8/pull/280 resolved the issue I was experiencing. Thank you!

TimelordUK / node-sqlserver-v8

Not catching results generated after PRINT or warning from stored procedures with NOCOUNT on #276