Skip to content

Unhandled exception in Parser.parseLengthCodedNumber #867

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
matthew-dean-hp opened this issue Jul 10, 2014 · 43 comments
Closed

Unhandled exception in Parser.parseLengthCodedNumber #867

matthew-dean-hp opened this issue Jul 10, 2014 · 43 comments
Labels

Comments

@matthew-dean-hp
Copy link

I have a stored procedure that needs to be called frequently and I have tried to make the call aware of my galera cluster by using a PoolCluster. If I send all the procedure calls to a single node in the cluster then everything works fine, however if I try to distribute the load by getting connections in a round-robin fashion I sometimes get the following exception when running the procedure:

TypeError: Cannot call method 'toString' of undefined
    at Parser.parseLengthCodedNumber (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:174:82)
    at FieldPacket.parse (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\packets\FieldPacket.js:46:31)
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:203:10)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:62:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:37:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:75:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)

I've managed to produce the simplest possible test case which can be done using the below SQL and node.js code. If I run the stored procedure SQL as individual statements the exception does not seem to happen and neither does it happen if I remove either the SELECT or the second INSERT. I'm pretty sure my cluster is set-up correctly and hopefully someone else is able to reproduce this. If it helps I'm running MariaDB 5.5.38.

CREATE TABLE `tbl_test` (
    `id` BIGINT(20) UNSIGNED NOT NULL AUTO_INCREMENT,
    `data` VARCHAR(128) NOT NULL,
    PRIMARY KEY (`id`),
    INDEX `data` (`data`)
)
ENGINE=InnoDB;

CREATE TABLE `tbl_testDep` (
    `id` BIGINT(20) UNSIGNED NOT NULL AUTO_INCREMENT,
    `test_fk` BIGINT(20) UNSIGNED NOT NULL,
    `data` VARCHAR(128) NOT NULL,
    PRIMARY KEY (`id`)
)
ENGINE=InnoDB;

DELIMITER $$

CREATE PROCEDURE `sp_runTest`(
    IN testData VARCHAR(128)
)
BEGIN   
        INSERT INTO `tbl_test` (`data`) VALUES (testData);
        INSERT INTO `tbl_testDep` (test_fk, `data`)
        SELECT `id`, `data` FROM `tbl_test` WHERE `data` = testData;
        SELECT * FROM `tbl_test` WHERE `data` = testData;
END $$

DELIMITER ;
var mysql = require('mysql');
var uuid = require('uuid');

var configA = {
        host: "hostA",
        port: 3306,
        database: "galeraTest",
        user: "root",
        password: "myreallysecurepassword"
};

var configB = {
        host: "hostB",
        port: 3306,
        database: "galeraTest",
        user: "root",
        password: "myreallysecurepassword"
};

var poolCluster = mysql.createPoolCluster();

poolCluster.add(configB);
poolCluster.add(configA);

var test = function() {
        poolCluster.getConnection(function (err, connection) {
                var data = uuid.v4();
                connection.query('CALL `sp_runTest`(?)', [data], function(err, rows) {
                        console.log(rows);
                        connection.release();
                })
                test();
        });
};
test();
@dougwilson
Copy link
Member

Wow, that you so much for the details explanation and the code, tables, etc. I'll work on investigating what is going on here :)

@dougwilson dougwilson added the bug label Jul 10, 2014
@dougwilson
Copy link
Member

@matthew-dean-hp are you able to reproduce the error reliably? I may have a fix and would like you to be able to also confirm the fix, especially since it involved a lot of changes.

@dougwilson
Copy link
Member

If at all possible, please install the current development version (npm install felixge/node-mysql) and try to reproduce the issue with debug: true in your connection configuration. If you get an error, please post the (possibly new error) along with some of the debug output right before the error.

@dougwilson
Copy link
Member

You can also try this with version 2.4.0

@matthew-dean-hp
Copy link
Author

I can reproduce this very easily so I'll give those versions a go later today and report back. Thanks for responding so promptly

@matthew-dean-hp
Copy link
Author

So here's the output after doing (npm install felixge/node-mysql) and adding -debug to the config. Sorry for the verbosity but I wasn't sure how much was relevant

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 81,
  scrambleBuff1: <Buffer 42 4d 3b 21 32 78 27 55>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 58 3a 59 33 30 38 65 75 3c 6b 27 7a>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 22 5c 7d b6 61 1b bf fa 20 2f 9f 70 97 a5 ff 46 56 9e 36 54>,
  database: 'galeraTest',
  protocol41: true }

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

--> ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'50ef6867-081c-4c64-bb4f-20f20d080ddc\')' }

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 1388,
  scrambleBuff1: <Buffer 26 4f 3a 73 56 34 41 2a>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 4b 7b 4c 4b 6f 6d 58 50 69 40 41 66>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 5c 25 56 ca 7d b8 68 f3 bc 72 78 87 be 7b f3 ec c1 a9 07 e7>,
  database: 'galeraTest',
  protocol41: true }

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

--> ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'f1587d7d-03fe-4252-acad-73b802730caf\')' }

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 82,
  scrambleBuff1: <Buffer 61 2b 4f 2f 3d 23 37 2b>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 6e 6a 4a 72 7e 46 7d 65 60 34 22 49>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 59 de 15 6a 3b 4c 4c 59 fb 93 95 e0 8f 29 81 c9 77 72 03 6c>,
  database: 'galeraTest',
  protocol41: true }

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

--> ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'9bed9ff2-32a0-4b4e-af94-8ccc13c880a6\')' }

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 1389,
  scrambleBuff1: <Buffer 47 7d 60 48 28 2c 46 5a>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 74 56 34 3e 7c 77 5e 51 5d 5e 42 6c>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 25 3c 50 bd a3 89 b6 a4 45 92 a8 1c 33 1a 91 3b 52 31 99 22>,
  database: 'galeraTest',
  protocol41: true }

<-- ResultSetHeaderPacket
{ fieldCount: 2, extra: undefined }

<-- FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'id',
  orgName: 'id',
  charsetNr: 63,
  length: 20,
  type: 8,
  flags: 16931,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true }

<-- FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'data',
  orgName: 'data',
  charsetNr: 33,
  length: 384,
  type: 253,
  flags: 20489,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true }

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

<-- RowDataPacket
{ id: 2, data: 'f1587d7d-03fe-4252-acad-73b802730caf' }

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

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

[ [ { id: 2, data: 'f1587d7d-03fe-4252-acad-73b802730caf' } ],
  { 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 }

--> ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'6388789d-6793-4a29-b947-5b47ead135f9\')' }

<-- ResultSetHeaderPacket
{ fieldCount: 2, extra: undefined }

<-- FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'id',
  orgName: 'id',
  charsetNr: 63,
  length: 20,
  type: 8,
  flags: 16931,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true }

<-- FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'data',
  orgName: 'data',
  charsetNr: 33,
  length: 384,
  type: 253,
  flags: 20489,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true }

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

<-- RowDataPacket
{ id: 3, data: '9bed9ff2-32a0-4b4e-af94-8ccc13c880a6' }

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

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

[ [ { id: 3, data: '9bed9ff2-32a0-4b4e-af94-8ccc13c880a6' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
<-- ResultSetHeaderPacket
{ fieldCount: 1, extra: 49 }

<-- FieldPacket
{ catalog: '5',
  db: '50ef6867-081c-4c64-bb4f-20f20d080ddc',
  table: '\u0000\u0000\u0003�\u0000',
  orgTable: '',
  name: '\u0000\u0007\u0000\u0000\u0004\u0000\u0000\u0000\u0002\u0000',
  orgName: '',
  charsetNr: undefined,
  length: undefined,
  type: undefined,
  flags: undefined,
  decimals: undefined,
  default: undefined,
  zeroFill: undefined,
  protocol41: true }

undefined

c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:82
        throw err;
              ^
TypeError: Cannot read property 'determinePacket' of undefined
    at Protocol._determinePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:275:15)
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:224:23)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:77:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:39:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:82:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)
    at emitReadable (_stream_readable.js:406:5)

@dougwilson
Copy link
Member

Thank you very much :) Unfortunately I'm still not 100% sure what is happening, so I'm going to have yet another version of this library for you to install and run the same debug stuff for some more collection later today.

@dougwilson
Copy link
Member

@matthew-dean-hp I just want to apologize for not getting back to you yesterday, I completely forgot about this.

@matthew-dean-hp
Copy link
Author

@dougwilson Any further progress on deducing the cause of this bug? If there's anything else I can do to help please just let me know

@dougwilson
Copy link
Member

Hi @matthew-dean-hp I'm so sorry. I plan to get you another version of this module that will provide me with more debugging information for you to paste back to me.

@dougwilson
Copy link
Member

I'm' sorry for the delay :( Can you please using the following command:

$ npm install felixge/node-mysql#debug

Then re-run your script to cause the issue and then post the new results? Hopefully this should be the last thing I need to determine what the issue is.

@matthew-dean-hp
Copy link
Author

So I'm pretty sure this isn't the result you were hoping for, but if I run with either or both configs in debug mode I cannot now reproduce the bug. If I run in non-debug mode for both configs I still get an unhandled exception but it has changed. Here's the last 100 lines or so:

[ [ { id: 102, data: '146742ff-dd0c-4f07-9a2c-15f850648579' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0 }
[ [ { id: 118, data: '33db554c-ab5c-4302-84e9-5a2409c91d3e' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 104, data: 'b3348c6d-1285-452d-8542-9e82306e2ced' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 106, data: 'a4eecabd-f2a4-4808-a404-8bd8d30cba18' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 119, data: '09ebd938-437e-4dbb-a9ab-8170a414f755' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 114, data: 'd85beb8a-2f9e-4fa1-897a-354763962dc7' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 112, data: '1ad1fbdf-ac27-4942-bbf0-e24f2d8712ee' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 120, data: 'b2542f41-1662-49ed-b3a3-7dbb39171c60' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
[ [ { id: 116, data: 'fd095f9e-00ac-495f-a1b2-02371fed0249' } ],
  { fieldCount: 0,
    affectedRows: 0,
    insertId: 0,
    serverStatus: 2,
    warningCount: 0,
    message: '',
    protocol41: true,
    changedRows: 0 } ]
undefined

c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:82
        throw err;
              ^
TypeError: Object #<Ping> has no method 'EofPacket'
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:265:24)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:77:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:39:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:82:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)
    at emitReadable (_stream_readable.js:406:5)
    at readableAddChunk (_stream_readable.js:168:9)

If all you've done is add extra debug lines then this is starting to feel to me like a race condition somewhere. Let me know if there's anything else I can do to help

@dougwilson
Copy link
Member

No, the error actually still looks just as wrong as all the others you've provided. Without the debug output, though, It's almost impossible for me to determine (you can actually exclude your console.log in the outputs, please :) ). I pushed an updated if you want to re-install the debug version and try it again.

@matthew-dean-hp
Copy link
Author

My apologies, I completely missed that. We do now have an error:

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 46,
  scrambleBuff1: <Buffer 67 3e 3c 51 63 21 73 44>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 38 2d 75 2a 6b 61 26 36 79 25 48 7b>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true,
  _header: { length: 102, number: 0 },
  _raw: <Buffer 0a 35 2e 35 2e 33 38 2d 4d 61 72 69 61 44 42 2d 31 7e 70 72 65 63 69 73 65 2d 77 73 72 65 70 2d 6c 6f 67 00 2e 00 00 00 67 3e 3c 51 63 21 73 44 00 ff f7 ...> }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 22 93 9a 7a 11 48 01 76 ea 54 7d 00 b8 42 cb 71 50 2c 2a 72>,
  database: 'galeraTest',
  protocol41: true }

<-- (43) ResultSetHeaderPacket
{ fieldCount: 2,
  extra: undefined,
  _header: { length: 1, number: 1 },
  _raw: <Buffer 02> }

<-- (43) FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'id',
  orgName: 'id',
  charsetNr: 63,
  length: 20,
  type: 8,
  flags: 16931,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true,
  _header: { length: 52, number: 2 },
  _raw: <Buffer 03 64 65 66 0a 67 61 6c 65 72 61 54 65 73 74 08 74 62 6c 5f 74 65 73 74 08 74 62 6c 5f 74 65 73 74 02 69 64 02 69 64 0c 3f 00 14 00 00 00 08 23 42 00 00 ...> }

<-- (43) FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'data',
  orgName: 'data',
  charsetNr: 33,
  length: 384,
  type: 253,
  flags: 20489,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true,
  _header: { length: 56, number: 3 },
  _raw: <Buffer 03 64 65 66 0a 67 61 6c 65 72 61 54 65 73 74 08 74 62 6c 5f 74 65 73 74 08 74 62 6c 5f 74 65 73 74 04 64 61 74 61 04 64 61 74 61 0c 21 00 80 01 00 00 fd ...> }

<-- (43) EofPacket
{ fieldCount: 254,
  warningCount: 0,
  serverStatus: 10,
  protocol41: true,
  _header: { length: 5, number: 4 },
  _raw: <Buffer fe 00 00 0a 00> }

<-- (43) RowDataPacket
{ _header: { length: 41, number: 5 },
  _raw: <Buffer 03 31 32 36 24 66 61 30 32 62 30 38 35 2d 66 66 61 39 2d 34 39 62 39 2d 39 38 36 31 2d 33 62 66 34 37 39 32 38 63 61 38 39>,
  id: 126,
  data: 'fa02b085-ffa9-49b9-9861-3bf47928ca89' }

<-- (43) EofPacket
{ fieldCount: 254,
  warningCount: 0,
  serverStatus: 10,
  protocol41: true,
  _header: { length: 5, number: 6 },
  _raw: <Buffer fe 00 00 0a 00> }

<-- (43) OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  _header: { length: 7, number: 7 },
  _raw: <Buffer 00 00 00 02 00 00 00>,
  changedRows: 0 }

<-- (46) OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  _header: { length: 7, number: 2 },
  _raw: <Buffer 00 00 00 02 00 00 00>,
  changedRows: 0 }

--> (43) ComPingPacket
{ command: 14 }

--> (46) ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'24fc7003-7560-49d0-a981-f6e6aea792b9\')' }

<-- (43) ResultSetHeaderPacket
{ fieldCount: 2,
  extra: undefined,
  _header: { length: 1, number: 1 },
  _raw: <Buffer 02> }

<-- (43) FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'id',
  orgName: 'id',
  charsetNr: 63,
  length: 20,
  type: 8,
  flags: 16931,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true,
  _header: { length: 52, number: 2 },
  _raw: <Buffer 03 64 65 66 0a 67 61 6c 65 72 61 54 65 73 74 08 74 62 6c 5f 74 65 73 74 08 74 62 6c 5f 74 65 73 74 02 69 64 02 69 64 0c 3f 00 14 00 00 00 08 23 42 00 00 ...> }

<-- (43) FieldPacket
{ catalog: 'def',
  db: 'galeraTest',
  table: 'tbl_test',
  orgTable: 'tbl_test',
  name: 'data',
  orgName: 'data',
  charsetNr: 33,
  length: 384,
  type: 253,
  flags: 20489,
  decimals: 0,
  default: undefined,
  zeroFill: false,
  protocol41: true,
  _header: { length: 56, number: 3 },
  _raw: <Buffer 03 64 65 66 0a 67 61 6c 65 72 61 54 65 73 74 08 74 62 6c 5f 74 65 73 74 08 74 62 6c 5f 74 65 73 74 04 64 61 74 61 04 64 61 74 61 0c 21 00 80 01 00 00 fd ...> }

<-- (43) EofPacket
{ fieldCount: 254,
  warningCount: 0,
  serverStatus: 10,
  protocol41: true,
  _header: { length: 5, number: 4 },
  _raw: <Buffer fe 00 00 0a 00> }

<-- (43) RowDataPacket
{ _header: { length: 41, number: 5 },
  _raw: <Buffer 03 31 32 37 24 37 62 32 31 66 63 65 63 2d 37 61 66 36 2d 34 39 65 36 2d 62 39 39 63 2d 61 64 32 62 33 35 63 39 36 30 37 34>,
  id: 127,
  data: '7b21fcec-7af6-49e6-b99c-ad2b35c96074' }

<-- (43) EofPacket
{ fieldCount: 254,
  warningCount: 0,
  serverStatus: 10,
  protocol41: true,
  _header: { length: 5, number: 6 },
  _raw: <Buffer fe 00 00 0a 00> }

<-- (43) OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  _header: { length: 7, number: 7 },
  _raw: <Buffer 00 00 00 02 00 00 00>,
  changedRows: 0 }

<-- (43) OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  _header: { length: 7, number: 1 },
  _raw: <Buffer 00 00 00 02 00 00 00>,
  changedRows: 0 }

--> (43) ComPingPacket
{ command: 14 }

--> (43) ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'a166756d-4f7c-4f02-97ea-5bef38cef149\')' }

<-- (44) ResultSetHeaderPacket
{ fieldCount: 3,
  extra: 49,
  _header: { length: 41, number: 1 },
  _raw: <Buffer 03 31 32 35 24 66 61 62 61 38 39 39 66 2d 35 33 32 36 2d 34 30 63 66 2d 39 39 37 61 2d 66 30 32 32 39 30 62 35 31 31 30 33> }

<-- (44) FieldPacket
{ catalog: '129',
  db: 'faba899f-5326-40cf-997a-f02290b51103',
  table: '\u0000\u0000\u0003�\u0000',
  orgTable: '',
  name: '\u0000\u0007\u0000\u0000\u0004\u0000\u0000\u0000\u0002\u0000',
  orgName: '',
  charsetNr: undefined,
  length: undefined,
  type: undefined,
  flags: undefined,
  decimals: undefined,
  default: undefined,
  zeroFill: undefined,
  protocol41: true,
  _header: { length: 41, number: 2 },
  _raw: <Buffer 03 31 32 39 24 66 61 62 61 38 39 39 66 2d 35 33 32 36 2d 34 30 63 66 2d 39 39 37 61 2d 66 30 32 32 39 30 62 35 31 31 30 33> }

=== Received packet without sequence in queue ===

c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:82
        throw err;
              ^
TypeError: Cannot read property '_packetHeader' of undefined
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:227:23)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:77:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:39:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:82:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)
    at emitReadable (_stream_readable.js:406:5)
    at readableAddChunk (_stream_readable.js:168:9)

@dougwilson
Copy link
Member

Awesome! I think this should do it. I saw from your error I actually made a really dumb typo in the code. I updated the debug version again if you're willing to re-run and re-post? :)

@dougwilson
Copy link
Member

Oh, and one one tweak to your posting instructions: since this occurs when there are multiple threads all running, I need to get the output from just one of them. So when you run it and see output with a bunch of garbage (like the name: '\u0000\u0007\u0000\u0000\u0004\u0000\u0000\u0000\u0002\u0000', like, which is garbage), take note of the header line for that packet (<-- (44) FieldPacket) and try to include the ones that have the same thread ID (44 in this case). You can also remove all the ones that have a different ID (like 46, etc.).

@matthew-dean-hp
Copy link
Author

How's this:

<-- HandshakeInitializationPacket
{ protocolVersion: 10,
  serverVersion: '5.5.38-MariaDB-1~precise-wsrep-log',
  threadId: 110,
  scrambleBuff1: <Buffer 22 2f 65 31 60 72 3f 23>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 224,
  serverStatus: 2,
  serverCapabilities2: 40975,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 2f 63 25 2d 52 37 5a 40 70 35 56 30>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true,
  _header: { length: 102, number: 0 },
  _raw: <Buffer 0a 35 2e 35 2e 33 38 2d 4d 61 72 69 61 44 42 2d 31 7e 70 72 65 63 69 73 65 2d 77 73 72 65 70 2d 6c 6f 67 00 6e 00 00 00 22 2f 65 31 60 72 3f 23 00 ff f7 ...> }

--> ClientAuthenticationPacket
{ clientFlags: 193487,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'root',
  scrambleBuff: <Buffer 39 ea e1 fc 00 33 80 cd 08 5d f4 4b 03 43 07 39 7f a1 5b 7a>,
  database: 'galeraTest',
  protocol41: true }

<-- (110) OkPacket
{ fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  _header: { length: 7, number: 2 },
  _raw: <Buffer 00 00 00 02 00 00 00>,
  changedRows: 0 }

--> (110) ComQueryPacket
{ command: 3,
  sql: 'CALL `sp_runTest`(\'586e925f-afdf-4f20-afd2-706ae8fb4de1\')' }

<-- (110) ResultSetHeaderPacket
{ fieldCount: 1,
  extra: 55,
  _header: { length: 39, number: 1 },
  _raw: <Buffer 01 37 24 35 38 36 65 39 32 35 66 2d 61 66 64 66 2d 34 66 32 30 2d 61 66 64 32 2d 37 30 36 61 65 38 66 62 34 64 65 31> }

<-- (110) FieldPacket
{ catalog: '11',
  db: '586e925f-afdf-4f20-afd2-706ae8fb4de1',
  table: '\u0000\u0000\u0003�\u0000',
  orgTable: '',
  name: '\u0000\u0007\u0000\u0000\u0004\u0000\u0000\u0000\u0002\u0000',
  orgName: '',
  charsetNr: undefined,
  length: undefined,
  type: undefined,
  flags: undefined,
  decimals: undefined,
  default: undefined,
  zeroFill: undefined,
  protocol41: true,
  _header: { length: 40, number: 2 },
  _raw: <Buffer 02 31 31 24 35 38 36 65 39 32 35 66 2d 61 66 64 66 2d 34 66 32 30 2d 61 66 64 32 2d 37 30 36 61 65 38 66 62 34 64 65 31> }

=== Received packet without sequence in queue ===
{ length: 5, number: 3 }
<Buffer fe 00 00 0a 00>


c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:82
        throw err;
              ^
TypeError: Cannot read property 'determinePacket' of undefined
    at Protocol._determinePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:289:15)
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:233:21)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:77:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:39:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:82:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)
    at emitReadable (_stream_readable.js:406:5)

@dougwilson
Copy link
Member

OK, that looks perfect :) I should be able to address it very soon! That you so much in helping me out here.

@dougwilson
Copy link
Member

By the way, have you tried to run the CALL query over and over on the standard (non-MariaDB) command line client to verify that, like, the server is not sending stuff that is not valid? I'm still looking into the protocol based on your trace there.

@dougwilson
Copy link
Member

Nevermind. I believe this is coming back as Multi-Resultset packets, which I don't think we support. I'll check it out and if so, we'll have support soon!

@dougwilson
Copy link
Member

@matthew-dean-hp can you add flags: '-MULTI_RESULTS' to your config and see if that makes it stop throwing errors for you?

@matthew-dean-hp
Copy link
Author

So it doesn't throw an unhandled exception but neither does the query actually execute. In the query callback I get an error of:

{ [Error: ER_SP_BADSELECT: PROCEDURE galeraTest.sp_runTest can't return a result set in the given context]
  code: 'ER_SP_BADSELECT',
  errno: 1312,
  sqlState: '0A000',
  index: 0 }

@dougwilson
Copy link
Member

but neither does the query actually execute

Right, I figured it wouldn't. I just wanted to confirm the issue is because we do not currently support "MULTI_RESULTS" yet the client is advertising it does to the server, which is why the exceptions are thrown.

Supporting "MULTI_RESULTS" itself is actually optional in the protocol and I'll add it, but I just wanted to make sure that was what you were seeing was all :) I've put in the feature request here: #885 This issue is basically that the library is lying about it's capabilities to the server.

@matthew-dean-hp
Copy link
Author

Well at least we've narrowed down the cause of the issue. One thing that is interesting is that if I run similar stored procedures in a non cluster aware fashion then everything works fine. This includes the return of multiple result sets from a CALL.

I know this is kind of a 'how long is a piece of string' type of question, but do you have an idea as to what sort of time-frame this might be implemented in? Not trying to hold you to anything, I'm just trying to get a best guess for my own planning.

@dougwilson
Copy link
Member

I know this is kind of a 'how long is a piece of string' type of question, but do you have an idea as to what sort of time-frame this might be implemented in?

I want to take a stab at it this weekend, so basically the intended timeline is very short :) I'm disappointed that it took so long just to figure out what it was in the first place, especially since this library was not sending the correct set of capabilities to the server, which would have brought up the issue as a feature request immediately and would probably have been implemented by now :)

@dougwilson
Copy link
Member

@matthew-dean-hp when you get the chance, can you try out your original code with the latest version from the following command to see if you're still experiencing the issue?

$ npm install felixge/node-mysql#debug

@matthew-dean-hp
Copy link
Author

It still gives an error

<-- (54) ResultSetHeaderPacket
{ fieldCount: 2,
  extra: 52,
  _header: { length: 40, number: 1 },
  _raw: <Buffer 02 34 32 24 39 37 32 37 38 64 33 63 2d 63 66 31 34 2d 34 31 33 31 2d 61 31 38 39 2d 32 61 33 37 30 31 35 61 62 63 38 33> }

<-- (54) FieldPacket
{ catalog: '60',
  db: '97278d3c-cf14-4131-a189-2a37015abc83',
  table: '\u0000\u0000\u0003�\u0000',
  orgTable: '',
  name: '\u0000\u0007\u0000\u0000\u0004\u0000\u0000\u0000\u0002\u0000',
  orgName: '',
  charsetNr: undefined,
  length: undefined,
  type: undefined,
  flags: undefined,
  decimals: undefined,
  default: undefined,
  zeroFill: undefined,
  protocol41: true,
  _header: { length: 40, number: 2 },
  _raw: <Buffer 02 36 30 24 39 37 32 37 38 64 33 63 2d 63 66 31 34 2d 34 31 33 31 2d 61 31 38 39 2d 32 61 33 37 30 31 35 61 62 63 38 33> }

=== Received packet without sequence in queue ===
{ length: 5, number: 3 }
<Buffer fe 00 00 0a 00>


c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:82
        throw err;
              ^
TypeError: Cannot read property 'determinePacket' of undefined
    at Protocol._determinePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:289:15)
    at Protocol._parsePacket (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:233:21)
    at Parser.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Parser.js:77:12)
    at Protocol.write (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\protocol\Protocol.js:39:16)
    at Socket.<anonymous> (c:\Users\deanmat\galeraTest\node_modules\mysql\lib\Connection.js:82:28)
    at Socket.emit (events.js:95:17)
    at Socket.<anonymous> (_stream_readable.js:748:14)
    at Socket.emit (events.js:92:17)
    at emitReadable_ (_stream_readable.js:410:10)
    at emitReadable (_stream_readable.js:406:5)

@dougwilson
Copy link
Member

Hm, I'm still at a loss here. Everything should be implemented and is testing fine. I'm going to go and install/setup a MariaDB to use, since that is what you are using instead of MySQL server. Have you tried against a MySQL server, or only against MariaDB?

My biggest roadblock so far is that I don't seem to be able to reproduce. I know you noted the following:

If I send all the procedure calls to a single node in the cluster then everything works fine, however if I try to distribute the load by getting connections in a round-robin fashion I sometimes get the following exception when running the procedure

So After I get MariaDB setup, I'm going to try and replicate that as much as I can.

@dougwilson
Copy link
Member

Another thing you can try in the meantime is perhaps replace your require('mysql') with require('mysql2') (from https://github.com/sidorares/node-mysql2) and see if that library has the same issue or not. The API between these two modules are generally the same and so should be a drop-in replacement, but the raw protocol parsers are very different, so it's a good thing to try out (we cross-post ours issues all the time).

@matthew-dean-hp
Copy link
Author

I haven't tried anything other than the specific mariadb version stated in the original post. I've tried mysql2 and it also throws a similar error. I'm also going to try and set up a mysql test to see if it's any different. Hopefully one of us works it out and it's just something with this specific version

@sidorares
Copy link
Member

Could you post an issue to mysql2 ( with debug enabled as well )?

@matthew-dean-hp
Copy link
Author

Done see sidorares/node-mysql2#113

@dougwilson
Copy link
Member

@matthew-dean-hp awesome, thanks :) I'll continue to research and follow with @sidorares finds. This issue is strange, indeed.

@matthew-dean-hp
Copy link
Author

So I've now managed to reproduce this on a pair of mysql 5.5.28 instances. Now I'm still not sure the exact cause of the problem but I've since discovered it only occurs with the setting:

innodb_locks_unsafe_for_binlog=0

I would therefore guess that the problem is somehow a conflict between two different calls and then the error is somehow not being handled correctly. I understand that the general recommendation, for performance reasons, is that this setting be 1 but I haven't found anywhere suggesting this is a requirement of galera. What do you think?

@matthew-dean-hp
Copy link
Author

One other thing. To reproduce the issue in mysql I followed this guide http://getasysadmin.com/2013/03/how-to-setup-galera-3-node-cluster-on-ubuntu-12-04/ creating two virtualbox instances with fresh installs of ubuntu 12.04. The only substantive difference is the above setting that had to be changed to break things. Hope that helps.

@sidorares
Copy link
Member

Some thoughts:

packets just before error:

0231362435613736633639652d343937652d343963372d393530312d61313562643930373933396505000003fe00000a00

  • length coded str "16"
  • length coded str "5a76c69e-497e-49c7-9501-a15bd907939e"
  • followed by 5, 0, 0, 3, 0xfe, 0, 0, 0xa, 0

"5, 0, 0, 3, 0xfe, 0, 0, 0xa, 0" is actually EOF packet (with header) - 0 warnings count, 0xa status flags
I don't know why it is merged with previous packet

@dougwilson
Copy link
Member

I don't know why it is merged with previous packet

As far as I have been able to determine it's either an issue in the code mixing the bytes up (though I now doubt that after I had @matthew-dean-hp test with a completely different algorithm and tested with mysql2), a network issue, or similar. I have not had time to go and setup a Galera cluster to test it out myself, though, in case that tells me something. If @matthew-dean-hp set it up on his end with two VIrtualBox instances, I can't see how it would be the network, though.

@matthew-dean-hp
Copy link
Author

@dougwilson, I really can't see this being packet corruption on the network. Whilst I could imagine an issue with virtualbox's internal network connections, I first came across this problem using two mysql instances on the same machine connected on a loopback interface.

@dougwilson
Copy link
Member

I really can't see this being packet corruption on the network. Whilst I could imagine an issue with virtualbox's internal network connections

It was just speculation :) I added "though I now doubt that", because, well, I don't think it is, especially because it changes based on a setting in the MySQL server.

@dougwilson
Copy link
Member

By the way, I just want to say sorry that this bug has been so crazy :( I hope you don't feel like we are ignoring you, but just the opposite :)

@matthew-dean-hp
Copy link
Author

I'm starting to think this is definitely a galera issue. Basically I've reconstructed the test using node-mariasql and it's returning to me occasionally an Error 2027, Malformed Packet. Given the vastly different pedigree of their library and this one it seems likely that this is either something peculiar in my setup or it's a very real bug in Galera. It would be very helpful if you could reproduce this just to make sure I'm not going crazy. There's still the issue of the unhandled-ness of the exception but I think that's probably it at your end. What do you think?

@dougwilson
Copy link
Member

using node-mariasql

Wow, that is actually using the C client library from MariaDB itself, so that really does make it seem like a server bug to me.

There's still the issue of the unhandled-ness of the exception but I think that's probably it at your end.

Yep. I'll make sure it's fixed :)

@dougwilson
Copy link
Member

So @matthew-dean-hp I know this is still an issue, but I think we can all agree that it may not be an issue with these clients, but rather something with the server. In the meantime, I have published 2.4.2 that should make all the errors you've posted above caused by this actually catch-able instead of crashing the Node.js process.

seangarner pushed a commit to seangarner/node-mysql that referenced this issue May 11, 2015
seangarner pushed a commit to seangarner/node-mysql that referenced this issue May 11, 2015
dveeden pushed a commit to dveeden/mysql that referenced this issue Jan 31, 2023
When `Dial()` returned error and it's `Timeout() == true`, return ErrBadConn to
database/sql retry new connection.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

No branches or pull requests

3 participants