ECDb: "Statement not closed" error log and occasional hangs

[grigasp]

Describe the bug

When running a test that creates a new ECDb and does some operations with it, I get an error log and occasional hangs.

To Reproduce

To reproduce the behavior, run this test multiple times:

it.only("Inserting into ECDb hangs the process", async function () {
  Logger.initializeToConsole();
  Logger.setLevelDefault(LogLevel.Warning);

  await IModelHost.startup();

  const ecdbPath = "/home/grigas/test.ecdb";
  IModelJsFs.unlinkSync(ecdbPath);
  const ecdb = new ECDb();
  ecdb.createDb(ecdbPath);

  const schemaXml = `
    <?xml version="1.0" encoding="UTF-8"?>
    <ECSchema schemaName="TestSchema" alias="Test" version="01.00.00" xmlns="http://www.bentley.com/schemas/Bentley.ECXML.3.2">
      <ECEntityClass typeName="X">
        <ECProperty propertyName="Label" typeName="string" />
      </ECEntityClass>
    </ECSchema>
  `;
  const schemaFilePath = "/home/grigas/test_schema.xml";
  fs.writeFileSync(schemaFilePath, schemaXml);
  ecdb.importSchema(schemaFilePath);
  ecdb.saveChanges();

  ecdb.withWriteStatement(`INSERT INTO Test.X (Label) VALUES (?)`, (stmt) => {
    stmt.bindString(1, "TestLabel 1");
    stmt.stepForInsert();
  });

  ecdb.saveChanges();
  ecdb.closeDb();

  ecdb.openDb(ecdbPath);
  for await (const entry of ecdb.createQueryReader(`SELECT * FROM Test.X`)) {
    // eslint-disable-next-line no-console
    console.log(JSON.stringify(entry.toRow()));
  }
  ecdb.closeDb();

  await IModelHost.shutdown();
});

Firstly, it logs a bunch of SQLite warnings and a BeSQLite error:

Warning | SQLite | rc=17, statement aborts at 33: [INSERT OR REPLACE INTO be_Prop (Namespace,Name,Id,SubId,TxnMode,RawSize,Data,StrData) VALUES(?,?,?,?,?,?,?,?)] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 11: [SELECT 1 FROM sqlite_master where type='table' AND name=?] database schema has changed 
Warning | SQLite | rc=284, automatic index on sqlite_master(type) 
Warning | SQLite | rc=17, statement aborts at 15: [SELECT Id,Type,ExclusiveRootClassId,ParentTableId FROM ec_Table WHERE Name=?] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 24: [SELECT Id,Name,Type,IsVirtual,NotNullConstraint,UniqueConstraint,CheckConstraint,DefaultConstraint,CollationConstraint,OrdinalInPrimaryKey,ColumnKind FROM main.ec_Column WHERE TableId= 
Warning | SQLite | rc=284, automatic index on sqlite_master(type) 
Warning | SQLite | rc=17, statement aborts at 15: [SELECT SchemaId,Name,DisplayLabel,Description,Type,Modifier,RelationshipStrength,RelationshipStrengthDirection,CustomAttributeContainerType FROM [main].ec_Class WHERE Id=?] database sc 
Warning | SQLite | rc=17, statement aborts at 17: [SELECT ClassId,Instance FROM [main].ec_CustomAttribute WHERE ContainerId=? AND ContainerType=? ORDER BY Ordinal] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 17: [SELECT ClassId,Instance FROM [main].ec_CustomAttribute WHERE ContainerId=? AND ContainerType=? ORDER BY Ordinal] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 14: [SELECT BaseClassId FROM [main].ec_ClassHasBaseClasses s WHERE ClassId=? ORDER BY Ordinal] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 34: [SELECT Id,Kind,Name,DisplayLabel,Description,IsReadonly,Priority,PrimitiveType,PrimitiveTypeMinLength,PrimitiveTypeMaxLength,PrimitiveTypeMinValue,PrimitiveTypeMaxValue,EnumerationId,S 
Warning | SQLite | rc=17, statement aborts at 10: [SELECT MapStrategy,ShareColumnsMode,MaxSharedColumnsBeforeOverflow,JoinedTableInfo FROM main.ec_ClassMap WHERE ClassId=?] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 18: [SELECT c.Id FROM main.ec_Class c JOIN main.ec_Schema s ON c.SchemaId = s.Id WHERE s.Name=?1 AND c.Name=?2] database schema has changed 
Warning | SQLite | rc=17, statement aborts at 20: [INSERT OR REPLACE INTO be_Local (Name,Val) VALUES(?,?)] database schema has changed 
Error | BeSQLite | Statement not closed: 'INSERT INTO [Test_X] ([Id],[Label]) VALUES (:_ecdb_ecsqlparam_id_col1,:_ecdb_ecsqlparam_ix1_col1)' 

Then, it usually passes, but occasionally one of these happens:

• The test hangs after passing.
• I get this in console after the test passes:

    ✔ Inserting into ECDb hangs the process
  
    1 passing (82ms)
  
  node: pthread_mutex_lock.c:438: __pthread_mutex_lock_full: Assertion `e != ESRCH || !robust' failed.
  

• I get this in console after the test passes:

    ✔ Inserting into ECDb hangs the process
  
    1 passing (72ms)
  
  node: tpp.c:83: __pthread_tpp_change_priority: Assertion `new_prio == -1 || (new_prio >= fifo_min_prio && new_prio <= fifo_max_prio)' failed.
  

• I get this in console after the test passes:

    ✔ Inserting into ECDb hangs the process
  
    1 passing (77ms)
  
  double free or corruption (!prev)
  

Expected behavior

No warnings, errors or hangs. The test should log {"ECInstanceId":"0x1","ECClassId":"0x58","Label":"TestLabel 1"} and pass.

Desktop (please complete the applicable information):

• OS: Ubuntu 22.04 (WSL)
• Node.js version: v20.18.2
• iTwin.js Version: 5.0.0-dev.111

[RohitPtnkr1996]

The ECSqlWriteStatement does not get disposed by itself after the callback finishes. stmt[Symbol.dispose]() needs to be called explicitly to release the native resources held.

[grigasp]

The ECSqlWriteStatement does not get disposed by itself after the callback finishes. stmt[Symbol.dispose]() needs to be called explicitly to release the native resources held.

Shouldn't withWriteStatement do that, though? Generally, an object is disposed by whoever holds its ownership, and in this case it's held internally by withWriteStatement function.

[RohitPtnkr1996]

Yup, that's true. I was just noting down what I noticed when I last looked at the code. We can fix that in this work item.