NodeJS / PHP problems when calling STORED PROCEDURES

Hi!

I’m having issues with STORED PROCEDURES when calling using NodeJS or PHP. My procedure should return or echo e Query result set (table) with the computed result. The procedure itself works in SingleStore Studio, and also works in my MySQL client (SequelPro), displaying the result set.

The issue is that when calling via the nodejs library (standard mysql library) the procedure execution does not return any data

Here is the protocol messages:

--> (2951593) ComQueryPacket {
  command: 3,
  sql: "CALL search_partners('SENOR ABRAVANEL')"
} 

<-- (2951593) OkPacket {
   fieldCount: 0,
   affectedRows: 0,
   insertId: 0,
   serverStatus: 2,
   warningCount: 0,
   message: '',
   protocol41: true,
   changedRows: 0
 }

I suspect two things:

  • The procedure, must use the RETURN statement or the ECHO SELECT statement in that case?
  • Is the protocol correct when calling the procedure with command 3 (normal query)?

Thanks,
Vinicius

If you want your SP to return a result, there are a number of ways to do it.

  1. Use “CALL spName(args)” and have the SP include in it’s body (usually as the last statement) and ECHO SELECT …; statement

  2. Have your SP return a scalar value or query-type value (QTV) but have your client app call it using ECHO spName(args)

See discussion of this in our documentation:



Hi @hanson,
Thanks for the quick reply.

After a little more digging, I was able to reproduce the problem. Sorry for the long reply.

Considering a simple SP, like this:

DELIMITER //

CREATE OR REPLACE PROCEDURE test_sp(v int)
  AS
  DECLARE
    c int = 1;
  BEGIN
    ECHO SELECT c + v as s;
  END //

DELIMITER ;

CALL test_sp(1); -- s = 2
CALL test_sp(2); -- s = 3

It works with following node code:

const mysql = require('mysql');

// MemSQL connections
const conn = mysql.createPool({
  connectionLimit: 10,
  host: process.env.MEMSQL_HOST,
  port: process.env.MEMSQL_PORT,
  user: process.env.MEMSQL_USER,
  password: process.env.MEMSQL_PASS,
  database: process.env.MEMSQL_DATABASE,
  debug: true,
  multipleStatements: true,
});

conn.query(`CALL test_sp(?)`, 1, (error, data) => {
  if (error) {
    console.log(error)
    conn.end();
    return;
  }

  console.log(data);
  conn.end();
});

And here is the protocol messages:

--> (3958195) ComQueryPacket { command: 3, sql: 'CALL test_sp(1)' }

<-- (3958195) ResultSetHeaderPacket { fieldCount: 1, extra: undefined }

<-- (3958195) FieldPacket {
  catalog: 'def',
  db: '',
  table: '',
  orgTable: '',
  name: 's',
  orgName: '',
  charsetNr: 63,
  length: 12,
  type: 8,
  flags: 128,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true
}

<-- (3958195) EofPacket {
  fieldCount: 254,
  warningCount: 0,
  serverStatus: 2,
  protocol41: true
}

<-- (3958195) RowDataPacket { s: 2 }

<-- (3958195) EofPacket {
  fieldCount: 254,
  warningCount: 0,
  serverStatus: 10,
  protocol41: true
}

<-- (3958195) OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

Now consider a similar SP with temporary tables:

DELIMITER //

CREATE OR REPLACE PROCEDURE test_sp_2(v int)
  AS
  DECLARE
    c int = 1;
  BEGIN
    DROP TABLE IF EXISTS temp_aux;
    CREATE TEMPORARY TABLE temp_aux(
      val int
    );
    DELETE FROM temp_aux;
    INSERT INTO temp_aux VALUES (c + v);

    ECHO SELECT val from temp_aux;
  END //

DELIMITER ;

Now the code breaks. Here is the protocol message:

--> (3958129) ComQueryPacket { command: 3, sql: 'CALL test_sp_2(1)' }

<-- (3958129) OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

And we get a PROTOCOL_PACKETS_OUT_OF_ORDER error.

This also happens if I don’t use the temporary table at all, for instance returning the following in the previous SP:
ECHO SELECT 1;

I have a SP that really needs a temporary table for computation. The strange thing is that this works fine at least with SingleStore Studio and Sequel Pro. A similar issue is happening with PHP as well.

This looks like something the server is doing wrong as it is not returning the result set before, or maybe it is returning it differently.

Please let me know if you need more info.

Simply adding the DROP table in the procedure causes the issue.

DELIMITER //

CREATE OR REPLACE PROCEDURE test_sp_3(v int) AS
  BEGIN
    DROP TABLE IF EXISTS table_that_does_not_exist;
    ECHO SELECT 1;
  END //

DELIMITER ;

That’s interesting. Can you post the versions of the drivers your using?

It looks like php\node.js may not like the Ok packet coming back in response to a query (though its a perfectly valid to a query - https://dev.mysql.com/doc/internals/en/com-query-response.html). Those are typically returned for DDL/write queries. They may be expecting the stored proc call to behave like a select and only return result sets and EOF packets.

It looks like multi-statement support is disabled by default in some drivers. Can you check on this?

Also, which version of Singlestore are you using?

-Adam

Hi @adam / @hanson,

Thanks for the answer.

The sample nodejs code I shared does have multipleStatements: true, but also changing it to false gives the same results. Also, as this is not a multiple statement query I would not think it is related to the problem.

Just to note, if the SP runs ECHO more than one time, which yields more than one resultset, it also works if no DDL statement is present:

DELIMITER //

CREATE OR REPLACE PROCEDURE test_sp(v int)
  AS
  DECLARE
    c int = 1;
  BEGIN
    ECHO SELECT c + v as s;
    ECHO SELECT c + v as s;
  END //

DELIMITER ;

Here is the package.json:

{
  "dependencies": {
    "mysql": "2.18.1"
  }
}

Also testing with the mysql2 library, the problem is the same.

I’m using the Managed SingleStore running version 7.3.2. NodeJS version 12.20.1.

Looking at the protocol you shared from MySQL docs, it does not look like the client should expect any data returning after the OK message is received. In the case some results are returned by the query, the ResultSet package should be sent. Please correct me if I’m reading it wrong.

Thanks,

Stored proc execution is relying on multi-statement support on the client to run multiple sql statements in one com query request inside the stored procedure (the client doesn’t know the stored proc is running a bunch of queries inside of it). In multi-statement mode the server is allowed to loop through and send multiple response packets (ok or result/eof). There is potentially some extra check the node.js client is doing the others aren’t, we’ll keep looking into it on our end.

Thanks for looking into it. I’m thinking about not using any DDL in the SP and instead use a normal table, and use some workaround with random key or something similar to simulate an empty table per execution, but that is not ideal.

I went with the temporary table within the procedure as it seems more elegant for my use case, and it is actually in the docs at the tree traversal sample, so I just assumed it would be a simple call and we would had no problems with it.

Hi @vkruoso,

SingleStore Studio actually uses the same driver as you in your example.

I tried to replicate this locally using the node.js version 12.20.1, mysqljs/mysql driver version 2.18.1, and a fresh cluster created from our Managed Service and I wasn’t able to replicate the PROTOCOL_PACKETS_OUT_OF_ORDER error yet.

Would it be possible for you to provide a repository with a simple example so I can try to reproduce it locally?

This is the snippet I used:

const mysql = require('mysql');

const pool = mysql.createPool({
  connectionLimit: 10,
  host: "MANAGED_SERVICE_HOST",
  user: "admin",
  password: "password",
  database: "database",
  debug: true,
  multipleStatements: true,
});

pool.query(`
CREATE OR REPLACE PROCEDURE test_sp_2(v int)
  AS
  DECLARE
    c int = 1;
  BEGIN
    DROP TABLE IF EXISTS temp_aux;
    CREATE TEMPORARY TABLE temp_aux(
      val int
    );
    DELETE FROM temp_aux;
    INSERT INTO temp_aux VALUES (c + v);

    ECHO SELECT val from temp_aux;
  END
`, (error, data) => {
  if (error) {
    console.log(error)
    return;
  }

  console.log(data)

  pool.query(`CALL test_sp_2(?)`, 2, (error, data2) => {
    if (error) {
      console.log(error)
      pool.end();
      return;
    }

    console.log(data2);
    console.log("success")
    pool.end();
  });

});

Am I missing something compared to your example?

Thanks!

Luis Neves

Hi @lneves,

Thanks for the snippet.

The same thing happens. Here is the full debug sequence:

<-- HandshakeInitializationPacket {
  protocolVersion: 10,
  serverVersion: '5.5.58',
  threadId: 5547410,
  scrambleBuff1: <Buffer 5f 52 23 33 46 4f 7d 53>,
  filler1: <Buffer 00>,
  serverCapabilities1: 65503,
  serverLanguage: 33,
  serverStatus: 2,
  serverCapabilities2: 32783,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 64 5d 73 7c 45 24 38 68 37 7b 4f 54>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true
}

--> (5547410) ClientAuthenticationPacket {
  clientFlags: 521167,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'admin',
  scrambleBuff: <Buffer ...>,
  database: 'leads',
  protocol41: true
}

<-- (5547410) OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

--> (5547410) ComQueryPacket {
  command: 3,
  sql: '\n' +
    'CREATE OR REPLACE PROCEDURE test_sp_4(v int)\n' +
    '  AS\n' +
    '  DECLARE\n' +
    '    c int = 1;\n' +
    '  BEGIN\n' +
    '    DROP TABLE IF EXISTS temp_aux;\n' +
    '    CREATE TEMPORARY TABLE temp_aux(\n' +
    '      val int\n' +
    '    );\n' +
    '    DELETE FROM temp_aux;\n' +
    '    INSERT INTO temp_aux VALUES (c + v);\n' +
    '\n' +
    '    ECHO SELECT val from temp_aux;\n' +
    '  END\n'
}

<-- (5547410) OkPacket {
  fieldCount: 0,
  affectedRows: 1,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

OkPacket {
  fieldCount: 0,
  affectedRows: 1,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}
<-- HandshakeInitializationPacket {
  protocolVersion: 10,
  serverVersion: '5.5.58',
  threadId: 5547411,
  scrambleBuff1: <Buffer 3d 69 26 2f 3d 7a 47 4d>,
  filler1: <Buffer 00>,
  serverCapabilities1: 65503,
  serverLanguage: 33,
  serverStatus: 2,
  serverCapabilities2: 32783,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 4d 68 6f 2a 6e 77 56 65 2c 3c 2f 47>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true
}

--> (5547411) ClientAuthenticationPacket {
  clientFlags: 521167,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'admin',
  scrambleBuff: <Buffer a4 45 74 92 74 24 74 99 9b d2 25 69 68 a8 fb 84 ba fe 69 d9>,
  database: 'leads',
  protocol41: true
}

<-- (5547411) OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

--> (5547411) ComQueryPacket { command: 3, sql: 'CALL test_sp_4(2)' }

<-- (5547411) OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}

OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0
}
success
--> (5547410) ComQuitPacket { command: 1 }

--> (5547411) ComQuitPacket { command: 1 }

/app/node_modules/mysql/lib/Pool.js:166
      if (err) throw err;
               ^

Error: Packets out of order. Got: 2 Expected: 1
    at Parser._tryReadPacketHeader (/app/node_modules/mysql/lib/protocol/Parser.js:470:15)
    at Parser.write (/app/node_modules/mysql/lib/protocol/Parser.js:33:29)
    at Protocol.write (/app/node_modules/mysql/lib/protocol/Protocol.js:38:16)
    at Socket.<anonymous> (/app/node_modules/mysql/lib/Connection.js:88:28)
    at Socket.<anonymous> (/app/node_modules/mysql/lib/Connection.js:526:10)
    at Socket.emit (events.js:314:20)
    at addChunk (_stream_readable.js:297:12)
    at readableAddChunk (_stream_readable.js:272:9)
    at Socket.Readable.push (_stream_readable.js:213:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:188:23)
    --------------------
    at Protocol._enqueue (/app/node_modules/mysql/lib/protocol/Protocol.js:144:48)
    at Protocol.quit (/app/node_modules/mysql/lib/protocol/Protocol.js:91:23)
    at PoolConnection.end (/app/node_modules/mysql/lib/Connection.js:239:18)
    at Pool._purgeConnection (/app/node_modules/mysql/lib/Pool.js:261:16)
    at Pool.end (/app/node_modules/mysql/lib/Pool.js:182:10)
    at Query.<anonymous> (/app/test.js:76:10)
    at Query.<anonymous> (/app/node_modules/mysql/lib/Connection.js:526:10)
    at Query._callback (/app/node_modules/mysql/lib/Connection.js:488:16)
    at Query.Sequence.end (/app/node_modules/mysql/lib/protocol/sequences/Sequence.js:83:24)
    at Query._handleFinalResultPacket (/app/node_modules/mysql/lib/protocol/sequences/Query.js:149:8) {
  code: 'PROTOCOL_PACKETS_OUT_OF_ORDER',
  fatal: true
}

Will try to provide a sample repository to reproduce.

Thanks,
Vinicius

Hi,

Here is the repository:

Turns out this works correctly. It fails only in the SingleStore Managed Service instance. So it looks like an issue with that cluster itself.

Thanks,
Vinicius

I figure this only happens when connecting to the aggregators to execute the procedure instead of the master node. We follow the recommendation to user the aggregators connection to run queries in the cluster, in that case, what would be the best practice?

There is a direct HA problem by always going to the master for all queries. Are there any other implications?

Hi Vinicius,

Just following up here. I can reproduce the issue when running the stored proc via a child aggregator. That was what the missing piece of information we needed. I have updated the task tracking this internally with this information.

-Adam

Just to close this and for someone facing the same issue: this was indeed a bug in the database. The support team helped debug and pinpoint the issue.

This is the release note:

2021-03-15 Version 7.3.6
Running DDL inside of stored procedures from child aggregators is now properly supported.

More details:

1 Like