Unexpected message type error connecting to Oracle 12c DB in thin mode

[GeorgeDewar]

1. What versions are you using?

I am using Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production.

process.platform: darwin
process.version: v16.20.0
process.arch: x64
require('oracledb').versionString: 6.0.3
require('oracledb').oracleClientVersionString: NJS-089: getting the Oracle Client version is not supported by node-oracledb in Thin mode

2. Is it an error or a hang or a crash?

It's an error.

3. What error(s) or behavior you are seeing?

$ node oracle_error.js

/Users/myname/code/appname/node_modules/oracledb/lib/errors.js:592
  throw (getErr(...arguments));
         ^

Error: NJS-103: unexpected message type 0 received at position 450 of packet 12
    at Object.throwErr (/Users/myname/code/appname/node_modules/oracledb/lib/errors.js:592:10)
    at AuthMessage.processMessage (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/messages/base.js:222:14)
    at AuthMessage.process (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/messages/base.js:200:12)
    at AuthMessage.decode (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/messages/base.js:190:10)
    at Protocol._decodeMessage (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/protocol.js:80:17)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Protocol._processMessage (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/protocol.js:155:9)
    at async ThinConnectionImpl.connect (/Users/myname/code/appname/node_modules/oracledb/lib/thin/connection.js:546:7)
    at async Object.getConnection (/Users/myname/code/appname/node_modules/oracledb/lib/oracledb.js:628:3)
    at async runApp (/Users/myname/code/appname/oracle_error.js:11:5) {
  code: 'NJS-103'
}

4. Include a runnable Node.js script that shows the problem.

oracle_error.js:

const oracledb = require('oracledb');

async function runApp() {
    let dbConfig = {
        user: '<redacted>',
        password: '<redacted>',
        connectString: '<redacted>:44901/<redacted>',
    };

    // Get a standalone Oracle Database connection
    await oracledb.getConnection(dbConfig);
    console.log('Connection was successful!');
}

runApp();

I did a little bit of debugging by adding console.log statements to node-oracledb locally, with the following results:

message.decode(this.readBuf); // pkt: 8, pos: 10
message.decode(this.readBuf); // pkt: 10, pos: 10
base.js decode, pos: 10, packet 10
base.js process, pos: 10, packet 10
hasMoreData? bytes left: 0, flushOutBinds: false
message.decode(this.readBuf); // pkt: 12, pos: 10
base.js decode, pos: 10, packet 12
base.js process, pos: 10, packet 12
Message type 8, pos: 11, packet 12
hasMoreData? bytes left: 180, flushOutBinds: false
Message type 23, pos: 304, packet 12
hasMoreData? bytes left: 34, flushOutBinds: false
Message type 0, pos: 450, packet 12

I have a packet trace and can provide details if needed, but won't share the whole thing here in case I inadvertently reveal something sensitive. Here's a screenshot though that shows Wireshark's interpretation of the packet in question, decoded as TNS:

[cjbj]

Thanks for the report.

[sharadraju]

@GeorgeDewar Is this issue consistently reproducible with your 12.2.0.1 database?
If possible, can you check with the 6.0.2 release and see if this issue is present with that version also?

[sudarshan12s]

@GeorgeDewar , Thanks for debug information. I see there is a server side piggyback , message type 23 during Authentication phase. Is it possible to share only the packet dump after this message type i.e at offset 304 on wards .

Example: Below this is the raw packet dump after offset 337

partial raw packet data from 336 offset onwards:

0336 : 00 04 01 01 02 33 6A 00 |.....3j.|
0344 : 00 00 00 00 00 00 00 00 |........|
0352 : 00 00 00 00 00 00 00 00 |........|
0360 : 00 00 01 00 00 00 00 00 |........|
0368 : 00 00 00      

Entire packet 12 raw data

2023-06-01 22:37:05.413 Receiving packet 12 on stream 1:
0000 : 00 00 01 73 06 00 00 00 |...s....|
0008 : 20 00 08 01 06 01 24 0C |......$.|
0016 : 41 55 54 48 5F 53 45 53 |AUTH_SES|
0024 : 53 4B 45 59 01 C0 40 32 |SKEY..@2|
0032 : 41 37 46 46 31 31 44 34 |A7FF11D4|
0040 : 32 37 42 41 33 37 43 42 |27BA37CB|
0048 : 42 35 31 42 44 45 36 33 |B51BDE63|
0056 : 37 31 34 33 39 34 38 39 |71439489|
0064 : 46 37 37 30 30 38 42 45 |F77008BE|
0072 : 45 45 39 31 39 46 37 31 |EE919F71|
0080 : 30 44 34 33 37 31 35 34 |0D437154|
0088 : 41 33 41 35 30 45 39 00 |A3A50E9.|
0096 : 01 27 0D 41 55 54 48 5F |.'.AUTH_|
0104 : 56 46 52 5F 44 41 54 41 |VFR_DATA|
0112 : 01 60 20 41 39 34 31 45 |.`.A941E|
0120 : 33 45 31 39 30 31 37 34 |3E190174|
0128 : 32 37 34 43 39 46 34 35 |274C9F45|
0136 : 37 42 30 38 39 44 43 44 |7B089DCD|
0144 : 41 43 42 02 48 15 01 3C |ACB.H..<|
0152 : 14 41 55 54 48 5F 50 42 |.AUTH_PB|
0160 : 4B 44 46 32 5F 43 53 4B |KDF2_CSK|
0168 : 5F 53 41 4C 54 01 60 20 |_SALT.`.|
0176 : 42 46 44 39 32 31 36 34 |BFD92164|
0184 : 43 38 34 44 37 32 46 31 |C84D72F1|
0192 : 31 31 34 41 34 42 38 30 |114A4B80|
0200 : 36 38 35 36 35 35 32 36 |68565526|
0208 : 00 01 42 16 41 55 54 48 |..B.AUTH|
0216 : 5F 50 42 4B 44 46 32 5F |_PBKDF2_|
0224 : 56 47 45 4E 5F 43 4F 55 |VGEN_COU|
0232 : 4E 54 01 0C 04 34 30 39 |NT...409|
0240 : 36 00 01 42 16 41 55 54 |6..B.AUT|
0248 : 48 5F 50 42 4B 44 46 32 |H_PBKDF2|
0256 : 5F 53 44 45 52 5F 43 4F |_SDER_CO|
0264 : 55 4E 54 01 03 01 33 00 |UNT...3.|
0272 : 01 4E 1A 41 55 54 48 5F |.N.AUTH_|
0280 : 47 4C 4F 42 41 4C 4C 59 |GLOBALLY|
0288 : 5F 55 4E 49 51 55 45 5F |_UNIQUE_|
0296 : 44 42 49 44 00 01 60 20 |DBID..`.|
0304 : 31 30 44 34 37 43 43 37 |10D47CC7|
0312 : 30 34 46 37 37 44 35 42 |04F77D5B|
0320 : 38 45 32 42 38 34 38 36 |8E2B8486|
0328 : 31 41 42 35 43 37 38 37 |1AB5C787|
0336 : 00 04 01 01 02 33 6A 00 |.....3j.|
0344 : 00 00 00 00 00 00 00 00 |........|
0352 : 00 00 00 00 00 00 00 00 |........|
0360 : 00 00 01 00 00 00 00 00 |........|
0368 : 00 00 00                |...     |

[GeorgeDewar]

Thank you both for responding.

@sharadraju it seems to be consistent, it has never behaved differently and it's doing the same this morning. I should mention that I've had no trouble with version 5.x using Instant Client. I've just tried with 6.0.2 and I get the same error, but without the helpful extra debugging info you added in 6.0.3.

@sudarshan12s sure. Here it is (offsets are in hex). 304 is 0x130, the second line of the output below, but I have included the line above because the last byte of that is the value (0x17 or 23) that it read as the message type. I think that might be a small bug in the error message - when it says "at position <n>" it's using buf.pos, but the actual message type value is at buf.pos - 1 since it advanced the position when it read the value.

0120   44 46 45 45 45 30 42 31 34 35 37 33 41 44 00 17   DFEEE0B14573AD..
0130   08 01 01 15 00 00 01 01 88 88 01 00 02 00 02 00   ................
0140   00 00 67 a4 77 a8 e3 50 5a d7 01 00 00 00 00 00   ..g.w..PZ.......
0150   00 00 67 ea 7d 38 00 00 00 00 00 00 00 00 88 00   ..g.}8..........
0160   00 00 0a 00 0a 00 00 00 00 00 00 00 00 00 00 00   ................
0170   00 00 00 00 00 00 00 00 00 00 00 01 00 00 02 00   ................
0180   00 00 7f 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0190   00 00 00 00 00 00 00 00 00 00 10 d4 a8 48 00 80   .............H..
01a0   3f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ?...............
01b0   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
01c0   00 00 04 01 01 01 02 00 00 00 00 00 00 00 00 00   ................
01d0   00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00   ................
01e0   00 00 00                                          ...

[sudarshan12s]

@GeorgeDewar , Thanks for sharing the trace. I think you need this patch to make it work. We will check and do a proper fix. Is it possible for you to verify with this small change in lib/thin/protocol/messages/base.js and confirm if it works.

@@ -260,7 +260,7 @@ class Message {
       buf.skipUB1();                            // skip queue
       const num_bytes = buf.readUB4();          // skip replay context
       if (num_bytes > 0) {
-        buf.skipBytes(num_bytes);
+        buf.skipBytesChunked();
       }
     } else if (opcode === constants.TNS_SERVER_PIGGYBACK_SESS_RET) {
       buf.skipUB2();

[GeorgeDewar]

Thank you @sudarshan12s! I've tried your patch, and now I get a different error:

Error: NJS-116: password verifier type 0x939 is not supported by node-oracledb in Thin mode
    at Object.throwErr (/Users/myname/code/appname/node_modules/oracledb/lib/errors.js:592:10)
    at AuthMessage.encode (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/messages/auth.js:206:20)
    at Protocol._encodeMessage (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/protocol.js:108:20)
    at Protocol._processMessage (/Users/myname/code/appname/node_modules/oracledb/lib/thin/protocol/protocol.js:151:18)
    at ThinConnectionImpl.connect (/Users/myname/code/appname/node_modules/oracledb/lib/thin/connection.js:547:28)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Object.getConnection (/Users/myname/code/appname/node_modules/oracledb/lib/oracledb.js:628:3)
    at async runApp (/Users/myname/code/appname/oracle_error.js:11:5)

I think this error is legit, so it means the patch solves the original problem, am I right? It looks like the same thing as this StackOverflow issue. Would you say it's a won't fix and we need to change the DB settings?

[sharadraju]

@GeorgeDewar for the password verifier error, please see my final comment in Issue #1584 . Yes, you would need to change the DB setting to use 11G or higher password verifiers.

Node-oracledb's Thin mode supports 11G and higher password verifiers, which are more secure.
To reset your password verifier to use more secure versions in your Oracle Database, please follow the steps listed here - Resetting Oracle Database password verifiers.

We are updating this in the documentation as well, FYI.

[sudarshan12s]

#1585

Yes @GeorgeDewar , I can see the patch worked in your case . Can you update the password verifier as 0x939 is based on DES, pretty old one and see with new verifier it works?

[GeorgeDewar]

Hi @sudarshan12s, sorry for the delay. I can confirm that connecting works with updated password verifier settings (our DBA created a new test account with the 10G, 11G and 12C versions enabled). I hugely appreciate your help on this issue!

[GeorgeDewar]

Hi @cjbj, although I said the patch worked, as far as I can tell it hasn't been applied to this repo yet. @sharadraju said in a message above he will "do a proper fix". Should this issue be kept open until that has happened?

[cjbj]

Sure!