Cannot unlock a never acquired lock

[andrii0lomakin]

Hi,
I get this error - any help on this?
This is the code that is causing the exception:

package test;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.List;
import java.util.concurrent.*;
import com.orientechnologies.orient.core.sql.query.OSQLSynchQuery;
import com.orientechnologies.orient.object.db.OObjectDatabaseTx;
public class CustomerTest3 {

 int  corePoolSize  =    2;
 int  maxPoolSize   =   3;
 long keepAliveTime = 500;
 public OObjectDatabaseTx db = new OObjectDatabaseTx(
   "plocal:c:/java/dbs/person").open("admin", "admin");
 public ExecutorService threadPoolExecutor =  new ThreadPoolExecutor(
            corePoolSize,
            maxPoolSize,
            keepAliveTime,
            TimeUnit.MILLISECONDS,
            new LinkedBlockingQueue<Runnable>()
            );



 public  CustomerTest3() {


 }
 public static void main(String[] args) {


  CustomerTest3 ct3 = new CustomerTest3();

  ct3.db.getEntityManager().registerEntityClasses("test"); 
  Future f1 = ct3.threadPoolExecutor.submit(new FutureTask<String>(
    new Callable<String>()
    { 
     public String call() {
      ct3.updateCust3();
      return "done";
     }
    }));

  Future f2 = ct3.threadPoolExecutor.submit(new FutureTask<String>(
    new Callable<String>()
    { 
     public String call() {
      ct3.updateCust4();
      return "done";
     }
    }));


//  try {
//   if (f1.get().equals("done") && f1.get().equals("done"))
//      ct3.db.close();
//  } catch (InterruptedException e) {
//   // TODO Auto-generated catch block
//   e.printStackTrace();
//  } catch (ExecutionException e) {
//   // TODO Auto-generated catch block
//   e.printStackTrace();
//  }


 }

  private void updateCust3() {
  List<Customer> result = db.query(new OSQLSynchQuery<Customer>(
    "select * from Customer where address.city like '%98%'"));

        SimpleDateFormat sdf = new SimpleDateFormat("MMM dd,yyyy HH:mm");



  for (Customer p : result) {
   //db.begin();

   p.setName("updated name " + sdf.format(new Date(System.currentTimeMillis())));

         System.out.println(sdf.format(new Date(System.currentTimeMillis())));

         System.out.println(p.getAddress().getCity());
         System.out.println(p.getName());
      db.save(p);
   try {
    Thread.sleep(5000);
   } catch (InterruptedException e) {
    // TODO Auto-generated catch block
    e.printStackTrace();
   }

   //db.commit();
  }
  }

  private void updateCust4() {
   List<Customer> result = db.query(new OSQLSynchQuery<Customer>(
     "select * from Customer where address.city like '%99%'"));

         SimpleDateFormat sdf = new SimpleDateFormat("MMM dd,yyyy HH:mm");



      for (Customer p : result) {


     p.setName("updated name " + sdf.format(new Date(System.currentTimeMillis())));

           System.out.println(sdf.format(new Date(System.currentTimeMillis())));

           System.out.println(p.getAddress().getCity());
           System.out.println(p.getName());

     try {
      Thread.sleep(1000);
     } catch (InterruptedException e) {
      // TODO Auto-generated catch block
      e.printStackTrace();
     }
     //db.begin();
     db.save(p);
     //db.commit();
    }

   }

}

/////////////////////////////////////////////////////////////////

Sep 24, 2014 3:48:31 PM com.orientechnologies.common.log.OLogManager log
SEVERE: Error on fetching record during browsing. The record has been skipped
com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #10:0 (cluster: customer)
at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:288)
at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.executeReadRecord(ODatabaseRecordAbstract.java:905)
at com.orientechnologies.orient.core.tx.OTransactionNoTx.loadRecord(OTransactionNoTx.java:70)
at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:274)
at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:40)
at com.orientechnologies.orient.core.iterator.OIdentifiableIterator.readCurrentRecord(OIdentifiableIterator.java:285)
at com.orientechnologies.orient.core.iterator.ORecordIteratorClusters.begin(ORecordIteratorClusters.java:287)
at com.orientechnologies.orient.core.iterator.ORecordIteratorClusters.config(ORecordIteratorClusters.java:376)
at com.orientechnologies.orient.core.iterator.ORecordIteratorClass.(ORecordIteratorClass.java:72)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLResultsetAbstract.searchInClasses(OCommandExecutorSQLResultsetAbstract.java:368)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.searchInClasses(OCommandExecutorSQLSelect.java:657)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLResultsetAbstract.assignTarget(OCommandExecutorSQLResultsetAbstract.java:128)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.assignTarget(OCommandExecutorSQLSelect.java:398)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.executeSearch(OCommandExecutorSQLSelect.java:382)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.execute(OCommandExecutorSQLSelect.java:349)
at com.orientechnologies.orient.core.sql.OCommandExecutorSQLDelegate.execute(OCommandExecutorSQLDelegate.java:60)
at com.orientechnologies.orient.core.storage.OStorageEmbedded.executeCommand(OStorageEmbedded.java:82)
at com.orientechnologies.orient.core.storage.OStorageEmbedded.command(OStorageEmbedded.java:71)
at com.orientechnologies.orient.core.sql.query.OSQLQuery.run(OSQLQuery.java:69)
at com.orientechnologies.orient.core.sql.query.OSQLSynchQuery.run(OSQLSynchQuery.java:80)
at com.orientechnologies.orient.core.query.OQueryAbstract.execute(OQueryAbstract.java:29)
at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.query(ODatabaseRecordAbstract.java:664)
at com.orientechnologies.orient.core.db.ODatabaseRecordWrapperAbstract.query(ODatabaseRecordWrapperAbstract.java:192)
at com.orientechnologies.orient.object.db.ODatabasePojoAbstract.query(ODatabasePojoAbstract.java:238)
at test.CustomerTest3.updateCust3(CustomerTest3.java:75)
at test.CustomerTest3.access$0(CustomerTest3.java:73)
at test.CustomerTest3$1.call(CustomerTest3.java:43)
at test.CustomerTest3$1.call(CustomerTest3.java:1)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:744)
Caused by: com.orientechnologies.common.concur.lock.OLockException: Cannot unlock a never acquired lock
at com.orientechnologies.orient.core.tx.OTransactionAbstract.unlockRecord(OTransactionAbstract.java:119)
at com.orientechnologies.orient.core.id.ORecordId.unlock(ORecordId.java:272)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.readRecord(OAbstractPaginatedStorage.java:1304)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.readRecord(OAbstractPaginatedStorage.java:661)
at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:282)
... 33 more

[andrii0lomakin]

Hi,
Could you provide test which I can run, in form of may be maven project ?

[andrii0lomakin]

Closed because of users report.

[mdymczyk]

@Laa any more details regarding this issue? I'm also getting a similar exception but I don't know if it's my fault or not:

2014-10-06 09:05:53.462 ERROR c.o.o.c.d.record.OLazyRecordIterator - Error on iterating record collection
com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #3:8242 (cluster: default)
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:260) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.executeReadRecord(ODatabaseRecordAbstract.java:1017) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.tx.OTransactionNoTx.loadRecord(OTransactionNoTx.java:65) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:251) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.record.ODatabaseRecordTx.load(ODatabaseRecordTx.java:40) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.ODatabaseRecordWrapperAbstract.load(ODatabaseRecordWrapperAbstract.java:227) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.ODatabaseRecordWrapperAbstract.load(ODatabaseRecordWrapperAbstract.java:52) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.id.ORecordId.getRecord(ORecordId.java:298) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.record.OLazyRecordIterator.next(OLazyRecordIterator.java:71) [orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.record.OLazyRecordIterator.next(OLazyRecordIterator.java:34) [orientdb-core-1.7.7.jar:1.7.7]
        at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) [guava-17.0.jar:na]
        ... 20 common frames omitted
Caused by: com.orientechnologies.orient.core.exception.OStorageException: Cannot route READ_RECORD operation against #3:8242 to the distributed node
        at com.orientechnologies.orient.server.distributed.ODistributedStorage.handleDistributedException(ODistributedStorage.java:967) ~[orientdb-server-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.server.distributed.ODistributedStorage.readRecord(ODistributedStorage.java:389) ~[orientdb-server-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.read(ODatabaseRaw.java:254) ~[orientdb-core-1.7.7.jar:1.7.7]
        ... 62 common frames omitted
Caused by: com.orientechnologies.common.concur.lock.OLockException: Cannot unlock a never acquired lock
        at com.orientechnologies.orient.core.tx.OTransactionAbstract.unlockRecord(OTransactionAbstract.java:119) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.id.ORecordId.unlock(ORecordId.java:272) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:1484) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.core.storage.impl.local.paginated.OLocalPaginatedStorage.readRecord(OLocalPaginatedStorage.java:745) ~[orientdb-core-1.7.7.jar:1.7.7]
        at com.orientechnologies.orient.server.distributed.ODistributedStorage.readRecord(ODistributedStorage.java:371) ~[orientdb-server-1.7.7.jar:1.7.7]
        ... 63 common frames omitted

I'm trying to return all the elements from a given cluster/class in a streaming fashion using an iterator so I have:

    public final class DbIterator implements Iterator<Map<String, Object>> {
        private final ORecordIteratorCluster<ODocument> innerIt;
        private final SortOrder order;
        private DatabaseProfile dbProfile;

        private DbIterator(DatabaseProfile dbProfile, String cluster, SortOrder order) {
            this.dbProfileProvider = dbProfileProvider;
            this.order = order;
            try (ODatabaseDocumentTx db = connect(dbProfile)) {
                this.innerIt = (SortOrder.asc.equals(order) ? db.browseCluster(cluster) : db.browseCluster(cluster).last());
            }
        }

        @Override
        public boolean hasNext() {
            try (ODatabaseDocumentTx db = connect(cluster)) {
                return SortOrder.asc.equals(order) ? innerIt.hasNext() : innerIt.hasPrevious();
            }
        }

        @Override
        public Map<String, Object> next() {
            try (ODatabaseDocumentTx db = connect(cluster)) {
                return SortOrder.asc.equals(order) ? documentToMap(innerIt.next()) : documentToMap(innerIt.previous());
            }
        }

        @Override
        public void remove() {
            throw new UnsupportedOperationException("Database iterator does not support remove operation. To remove records from the DB use an appropriate API call.");
        }

    }

I'm wondering should I even do this? Might there be a possible concurrent issue here is someone at the same time modifies that cluster?

I'm still using 1.7.7, though (no I didn't try newer versions because those don't boostrap for me due to other bugs).

I'm calling hasNext() before every next() call and those seem to work fine.

[andrii0lomakin]

Hi,

What is source code for connect ?

Could you do this in 3 steps if you use distributed storage ?

I mean start with embedded local storage and check whether you have exception.
If you do not have exception, which means that it is a bug, could you do the same for remote storage , if you once again do not have issue, so it is distributed storage bug.

As result we find layer which is responsible for issue.

[mdymczyk]

connect() is kind of trivial:

private static ODatabaseDocumentTx connect(DatabaseProfile dbProfile) {
        return ODatabaseDocumentPool.global().acquire(dbProfile.getFullDBLocation(), dbProfile.getAuthCredentials().getUser(), dbProfile.getAuthCredentials().getPassword());
    }

I will try running it in non distributed mode.

[andrii0lomakin]

Could you check whether db instance is the same during iteration, I suppose it should I prefer to be sure.

[mdymczyk]

Does it have to be the same instance? I guess since each call to next() is calling the pool it doesn't have to be the case and the db instance might be different. The ORecordIteratorCluster<ODocument> is the same every time, though.

I don't store a ODatabaseDocumentTx instance in my iterator as I would have to somehow know when to close it which would greatly complicate my code - that's why I went with a db pool call per next()/hasNext() invocation.

[andrii0lomakin]

Hi,
You never close pool and use it from the same thread so it should use the same instance.
But I think you asked whether iterator should use the same instance, answer is it was created with this in mind. It is duplication of #2866. You should wait till it was fixed and retry.