SNOW-995562: Repeated queries using requestId - apparently divergent behavior b/t CREATE TABLE & INSERT?

[n0land0]

Please answer these questions before submitting your issue.
In order to accurately debug the issue this information is required. Thanks!

1. What version of NodeJS driver are you using?
   1.9.2

2. What operating system and processor architecture are you using?
   macOS / arm64

3. What version of NodeJS are you using?
   (node --version and npm --version)
   node 18.11.0 / npm 8.19.2

4. What are the component versions in the environment (npm list)?'
   [email protected]

5.Server version:* E.g. 1.90.1
You may get the server version by running a query:

SELECT CURRENT_VERSION();

7.44.2

6. What did you do?

I've been seeing some unexpected behavior on queries with a shared requestId in my app environment, reproduced in plain JS here. Apologies for the lengthy code, as part of what I'm encountering is unexpectedly divergent behavior between these 2 examples.

const snowflake = require("snowflake-sdk");
const process = require("process");

const credentials = {
  account: process.env.REPRO_SF_ACCOUNT,
  username: process.env.REPRO_SF_USERNAME,
  password: process.env.REPRO_SF_PASSWORD,
};

const getConnection = () => {
  return new Promise((resolve, reject) => {
    const connection = snowflake.createConnection(credentials);
    connection.connect((err, conn) => (err ? reject(err) : resolve(conn)));
  });
};

const execute = (conn, sqlText, requestId) => {
  return new Promise((resolve, reject) => {
    const query = {
      sqlText,
      complete: (err, stmt, rows) =>
        err ? reject(err) : resolve({ stmt, rows }),
    };
    if (requestId) {
      query.requestId = requestId;
    }
    conn.execute(query);
  });
};

const destroy = (conn) => {
  return new Promise((resolve, reject) =>
    conn.destroy((err) => (err ? reject(err) : resolve()))
  );
};

const TEST_TABLE = `"<your db here>"."<your schema here>"."<your table here>"`;

const sqlTextCreateTable = `CREATE TABLE ${TEST_TABLE} (
  <your column definitions here>
)`;

const createTableExample = async () => {
  const conn = await getConnection();

  try {
    await execute(conn, `DROP TABLE IF EXISTS ${TEST_TABLE}`);
    const { stmt, rows: rows } = await execute(conn, sqlTextCreateTable);
    console.log({ rows });

    const requestId1 = stmt.getRequestId();
    await execute(conn, sqlTextCreateTable, requestId1);
  } catch (err) {
    console.log("Got an error:", err);
  } finally {
    await destroy(conn);
  }
};

const sqlTextInsertRow = `INSERT INTO ${TEST_TABLE} (<your column names here>) VALUES (<your column values here>)`;
const sqlTextGetMatchingRows = `SELECT * FROM ${TEST_TABLE} WHERE <condition matching some value you just inserted>`;

const insertRowExample = async () => {
  const conn = await getConnection();

  try {
    await execute(conn, `DROP TABLE IF EXISTS ${TEST_TABLE}`);
    await execute(conn, sqlTextCreateTable);

    const { stmt: stmtInsertRow1 } = await execute(conn, sqlTextInsertRow);

    const { rows: rowsGetMatching1 } = await execute(
      conn,
      sqlTextGetMatchingRows
    );
    console.log({ rowsGetMatching1 });

    const requestId1 = stmtInsertRow1.getRequestId();
    await execute(conn, sqlTextInsertRow, requestId1);

    const { rows: rowsGetMatching2 } = await execute(
      conn,
      sqlTextGetMatchingRows
    );
    console.log({ rowsGetMatching2 });
  } catch (err) {
    console.log("Got an error:", err);
  } finally {
    await destroy(conn);
  }
};

// run one at a time
// createTableExample();
// insertRowExample();

7. What did you expect to see? What should have happened and what happened instead?

For 2 repeated instances of a given query sharing the same requestId, I expected to see an indication that the second instance of the query was not being executed. More to the point, though, I expected to see consistent behavior across these two examples, but this doesn't seem to be the case.

The results I see from createTableExample above indicate that the CREATE TABLE query is being run both times despite the presence of a shared requestId. (Second query run yields [OperationFailedError]: SQL compilation error: Object <object> already exists).

By contrast, the insertRowExample results show the behavior I'd expect, a row only being inserted on the first query (I tested this more thoroughly but kept the example code here brief).

8. Can you set logging to DEBUG and collect the logs?

   https://community.snowflake.com/s/article/How-to-generate-log-file-on-Snowflake-connectors

e.g
Add this to get standard output.

var snowflake = require('snowflake-sdk');
snowflake.configure(
{
  logLevel: 'trace'
});

[sfc-gh-dszmolka]

hi - thank you for submitting this issue. we'll take a look.

[sfc-gh-dszmolka]

🎉 Happy new year ;) and thank you for your patience here. Took a look into this. Appreciate sharing the reproduction code; it is always very helpful to be able to see what the issue reporter is doing.

Before going into the bug territory, i would like to confirm what exactly the unexpected behaviour here.
Per the Snowflake documentation for resubmitting requests:

If you choose to resubmit a request with a requestId and sqlText, be aware of the following interactions:

• If the requestId already exists, meaning it matches a previous request, the command ignores the sqlText query and resubmits the query from the original command.
• If the requestId does not exist, meaning it does not match a previous request, the command executes the sqlText query.

The main use-case for this functionality is to be able to resubmit requests, in case they failed to reach the backend in the first place.

So per the above documentation, behaviour could be said it's expected. This is exactly what happens. The query is indeed resubmitted from the original command (and fails because the original command executed successfully). On the server side, the INSERT is not executed again.

However comparing it with the SQL REST API behaviour which is referenced from the Node.js driver documentation, it says

[..]If you specify the same request ID in the initial request along with the retry=true parameter in the resubmitted request, Snowflake does not execute the statement again if the statement has already been executed successfully.

Tested this and with the SQL REST API, it works the same even with the CREATE statement the same way as it works with the INSERT with the Node.js driver; i.e. the driver does not really execute the same statement twice; instead it returns the successful response from the backend which comes from the first request.

$ curl -i -X POST \
    -H "Content-Type: application/json" \
    -H "Authorization: Bearer $JWT" \
    -H "Accept: application/json" \
    -H "User-Agent: myApplicationName/1.0" \
    -H "X-Snowflake-Authorization-Token-Type: KEYPAIR_JWT" \
    -d "@request-body.json" \
    "https://myaccount.eu-central-1.snowflakecomputing.com/api/v2/statements
..
  "data" : [ ["Table NODEJS_GH740 successfully created."] ],
  "code" : "090001",
  "statementStatusUrl" : "/api/v2/statements/01b1391d-0102-4c1b-0002-477600107006?requestId=039f5ee0-def1-4df9-978d-3eccbd0e33fb",
  "requestId" : "039f5ee0-def1-4df9-978d-3eccbd0e33fb",
  "sqlState" : "00000",
  "statementHandle" : "01b1391d-0102-4c1b-0002-477600107006",

### resubmit the same requestID (039f5ee0-def1-4df9-978d-3eccbd0e33fb) with the same request body, the CREATE TABLE
### with retry=true flag
$ curl -i -X POST \
    -H "Content-Type: application/json" \
    -H "Authorization: Bearer $JWT" \
    -H "Accept: application/json" \
    -H "User-Agent: myApplicationName/1.0" \
    -H "X-Snowflake-Authorization-Token-Type: KEYPAIR_JWT" \
    -d "@request-body.json" \
    "https://myaccount.eu-central-1.snowflakecomputing.com/api/v2/statements?requestId=039f5ee0-def1-4df9-978d-3eccbd0e33fb&retry=true"
..
  "data" : [ ["Table NODEJS_GH740 successfully created."] ],
  "code" : "090001",
  "statementStatusUrl" : "/api/v2/statements/01b1391d-0102-4c1b-0002-477600107006?requestId=039f5ee0-def1-4df9-978d-3eccbd0e33fb",
  "requestId" : "039f5ee0-def1-4df9-978d-3eccbd0e33fb",
  "sqlState" : "00000",
  "statementHandle" : "01b1391d-0102-4c1b-0002-477600107006",
  "message" : "Statement executed successfully.",

same queryID (= statementHandle) as from the first query, meaning, it wasn't executed again but instead result from first query was returned.
This works for the INSERT query in the Node.js driver, doesn't look like it works the same for the DDL.

Bottom line: the driver works per documentation, still divergent from other client. We'll take a look to see if it's a genuine bug or how the driver is indeed expected to work (documentation suggests so).

In the meantime as a workaround, using CREATE as CREATE IF NOT EXISTS could help to tackle both scenarios (table exists vs table does not exist yet)