Callback in promise never called

[mebibou]

For some reason the then functions from the queries are never called for me. For example:

connection.query('SELECT * FROM information_schema.statistics').then(results => console.log(results));

Will never display the results. I put a console.log in the source code of this library at command.js#successEnd (before the process.nextTick(this.resolve, val);) and the val does contain the data, but the promise seems to never resolve for some reason.

$ node -v
v10.1.0

Testing on 2.0.0-alpha

[rusher]

Hi @mebibou,
I've tried to reproduced your issue with node.js v10.1.0 and connector 2.0.0-alpha without success.

Can you share some code part / your dependencies list ?
and try simple code like:

const mariadb = require('mariadb');
mariadb.createConnection({user:'root'}).then(connection => {
  connection.query('SELECT * FROM information_schema.statistics')
  .then(results => {
    console.log(results);
    connection.end();
  });

});

[mebibou]

@rusher this simple code throws this error:

events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: (conn=64957, no: 45011, SQLState: 08S01) receiving packet from server without active commands
conn:64957(0,80)
03 64 65 66 12 69 6E 66  6F 72 6D 61 74 69 6F 6E     .def.information
5F 73 63 68 65 6D 61 0A  73 74 61 74 69 73 74 69     _schema.statisti
63 73 0A 53 54 41 54 49  53 54 49 43 53 0A 49 4E     cs.STATISTICS.IN
44 45 58 5F 4E 41 4D 45  0A 49 4E 44 45 58 5F 4E     DEX_NAME.INDEX_N
41 4D 45 0C E0 00 00 01  00 00 FD 01 00 00 00 00     AME.............

    at Object.module.exports.createError ([...]/node_modules/mariadb/lib/misc/errors.js:55:10)
    at Connection._unexpectedPacket ([...]/node_modules/mariadb/lib/connection.js:660:16)
    at PacketInputStream.receivePacket ([...]/node_modules/mariadb/lib/io/packet-input-stream.js:46:12)
    at PacketInputStream.onData ([...]/node_modules/mariadb/lib/io/packet-input-stream.js:107:20)
    at Socket.emit (events.js:182:13)
    at addChunk (_stream_readable.js:277:12)
    at readableAddChunk (_stream_readable.js:262:11)
    at Socket.Readable.push (_stream_readable.js:217:10)
    at TCP.onread (net.js:638:20)
Emitted 'error' event at:
    at Connection._unexpectedPacket ([...]/node_modules/mariadb/lib/connection.js:658:12)
    at PacketInputStream.receivePacket ([...]/node_modules/mariadb/lib/io/packet-input-stream.js:46:12)
    [... lines matching original stack trace ...]
    at TCP.onread (net.js:638:20)

I ran the code in an empty project with only the mariadb as dependency

[rusher]

Then it seems, there is a protocol issue.
could you indicate server type and version, and add debug to connection string, to have complete exchanges with server logged ?
(i.e. : with previous example: )

const mariadb = require('mariadb');
mariadb.createConnection({user: 'root', debug: true}).then(connection => {
  console.log(connection.serverVersion());
  connection.query('SELECT * FROM information_schema.statistics')
  .then(results => {
    console.log(results);
    connection.end();
  });
});

[mebibou]

Yes I am using a MySQL server on Azure, version 5.7. With the logs:

<== conn:-1 Handshake.parseHandshakeInit (0,76)
4C 00 00 00 0A 35 2E 36  2E 33 39 2E 30 00 E0 FC     L....5.6.39.0...
00 00 FE FE FE FE FE FE  FE FE 00 0F AB 21 02 00     .............!..
3F 00 15 00 00 00 00 00  00 00 00 00 00 FE FE FE     ?...............
FE FE FE FE FE FE FE FE  FE 00 6D 79 73 71 6C 5F     ..........mysql_
6E 61 74 69 76 65 5F 70  61 73 73 77 6F 72 64 00     native_password.

==> conn:64736 Handshake.parseHandshakeInit(0,104)
64 00 00 01 02 A3 AE 00  00 00 00 40 E0 00 00 00     d..........@....
00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00     ................
00 00 00 00 63 72 61 64  6D 69 6E 40 63 6C 65 61     ....<user>@
72 72 6F 61 64 6C 61 62  2D 64 65 76 00 14 DD 48     <host>...H
A9 B5 AC E4 DF 1C 88 7F  66 4D 03 DC 58 48 D0 C8     ........fM..XH..
6C 28 6D 79 73 71 6C 5F  6E 61 74 69 76 65 5F 70     l(mysql_native_p
61 73 73 77 6F 72 64 00                              assword.

<== conn:64736 Handshake.handshakeResult (0,44)
2C 00 00 02 FE 6D 79 73  71 6C 5F 6E 61 74 69 76     ,....mysql_nativ
65 5F 70 61 73 73 77 6F  72 64 00 57 2D 25 10 62     e_password.W-%.b
2B 50 21 63 40 20 1E 01  18 74 77 07 4D 37 25 00     +P!c@ ...tw.M7%.

==> conn:64736 NativePasswordAuth(0,24)
14 00 00 03 BE F1 A6 BF  72 4F B7 D6 D2 D3 78 C5     ........rO....x.
4B 0E CE E8 FE 05 BE 4A                              K......J

<== conn:64736 Handshake.handshakeResult (0,7)
07 00 00 04 00 00 00 02  00 00 00                    ...........

==> conn:64736 Query(0,48)
2C 00 00 00 03 53 45 4C  45 43 54 20 2A 20 46 52     ,....SELECT * FR
4F 4D 20 69 6E 66 6F 72  6D 61 74 69 6F 6E 5F 73     OM information_s
63 68 65 6D 61 2E 73 74  61 74 69 73 74 69 63 73     chema.statistics

<== conn:64736 NativePasswordAuth.response (0,1)
01 00 00 01 10                                       .....

<== conn:64736 Query.readResponsePacket (0,86)
56 00 00 02 03 64 65 66  12 69 6E 66 6F 72 6D 61     V....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0D 54 41 42 4C 45 5F  43 41 54 41 4C 4F 47 0D     S.TABLE_CATALOG.
54 41 42 4C 45 5F 43 41  54 41 4C 4F 47 0C E0 00     TABLE_CATALOG...
00 08 00 00 FD 01 00 00  00 00                       ..........

<== conn:64736 Query.readColumn (0,84)
54 00 00 03 03 64 65 66  12 69 6E 66 6F 72 6D 61     T....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0C 54 41 42 4C 45 5F  53 43 48 45 4D 41 0C 54     S.TABLE_SCHEMA.T
41 42 4C 45 5F 53 43 48  45 4D 41 0C E0 00 00 01     ABLE_SCHEMA.....
00 00 FD 01 00 00 00 00                              ........

<== conn:64736 Query.readColumn (0,80)
50 00 00 04 03 64 65 66  12 69 6E 66 6F 72 6D 61     P....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0A 54 41 42 4C 45 5F  4E 41 4D 45 0A 54 41 42     S.TABLE_NAME.TAB
4C 45 5F 4E 41 4D 45 0C  E0 00 00 01 00 00 FD 01     LE_NAME.........
00 00 00 00                                          ....

<== conn:64736 Query.readColumn (0,80)
50 00 00 05 03 64 65 66  12 69 6E 66 6F 72 6D 61     P....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0A 4E 4F 4E 5F 55 4E  49 51 55 45 0A 4E 4F 4E     S.NON_UNIQUE.NON
5F 55 4E 49 51 55 45 0C  3F 00 01 00 00 00 08 01     _UNIQUE.?.......
00 00 00 00                                          ....

<== conn:64736 Query.readIntermediateEOF (0,84)
54 00 00 06 03 64 65 66  12 69 6E 66 6F 72 6D 61     T....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0C 49 4E 44 45 58 5F  53 43 48 45 4D 41 0C 49     S.INDEX_SCHEMA.I
4E 44 45 58 5F 53 43 48  45 4D 41 0C E0 00 00 01     NDEX_SCHEMA.....
00 00 FD 01 00 00 00 00                              ........

<== conn:64736 no command (0,80)
50 00 00 07 03 64 65 66  12 69 6E 66 6F 72 6D 61     P....def.informa
74 69 6F 6E 5F 73 63 68  65 6D 61 0A 73 74 61 74     tion_schema.stat
69 73 74 69 63 73 0A 53  54 41 54 49 53 54 49 43     istics.STATISTIC
53 0A 49 4E 44 45 58 5F  4E 41 4D 45 0A 49 4E 44     S.INDEX_NAME.IND
45 58 5F 4E 41 4D 45 0C  E0 00 00 01 00 00 FD 01     EX_NAME.........
00 00 00 00                                          ....

events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: (conn=64736, no: 45011, SQLState: 08S01) receiving packet from server without active commands
conn:64736(0,80)
03 64 65 66 12 69 6E 66  6F 72 6D 61 74 69 6F 6E     .def.information
5F 73 63 68 65 6D 61 0A  73 74 61 74 69 73 74 69     _schema.statisti
63 73 0A 53 54 41 54 49  53 54 49 43 53 0A 49 4E     cs.STATISTICS.IN
44 45 58 5F 4E 41 4D 45  0A 49 4E 44 45 58 5F 4E     DEX_NAME.INDEX_N
41 4D 45 0C E0 00 00 01  00 00 FD 01 00 00 00 00     AME.............

[rusher]

problem identified:

<== conn:64736 NativePasswordAuth.response (0,1)
01 00 00 01 10                                       .....

That means a race condition there. (First query packet is handle by authentication command and not query command).

[mebibou]

ok... what does that mean? 🙄
btw, forgot to add the log of the exact version, it gives 5.6.39.0

[rusher]

Error reproduced, it concern authentication switch.
correction is done with commit 9d1a0cf on develop branch. This will be released next week, or you can try downloading project and using develop branch now.

I'm just wondering, this MySQL has an issue because ask for standard mysql_native_password authentication, connector answer for it, with encrypted authentication, at this point, the connection must be established.
But server asks another time for mysql_native_authentication (using pluggable authentication). Connector give back another time encrypted password. This means connection taking 2 times more than expected