5 Replies Latest reply on May 9, 2007 9:58 PM by jason.greene

    Threading Bug in PojoCache?

    vincent.marquez

      I have strong reason to suspect a bug in jbossCache which can result in an exception being thrown when multiple threads are dealing with an object. I discovered this when I was adding a pojo to a cached/advised ArrayList, and at the same time in another thread reading data from that pojo.

      The exception being thrown:

      org.jboss.cache.pojo.PojoCacheException: PojoCacheDelegate.getObjectInternal(): null PojoInstance for fqn: /__JBossInternal__/cachedVars/class JoinPoint_w_clients_4clients/_ID_/a232u-bqwm2c-f0vhanwn-1-f0vhb667-h
      at org.jboss.cache.pojo.impl.PojoCacheDelegate.getObjectInternal(PojoCacheDelegate.java:341)
      at org.jboss.cache.pojo.impl.PojoCacheDelegate.getObject(PojoCacheDelegate.java:109)
      at org.jboss.cache.pojo.impl.PojoCacheImpl.getObject(PojoCacheImpl.java:203)
      at org.jboss.cache.pojo.interceptors.dynamic.CacheFieldInterceptor.invoke(CacheFieldInterceptor.java:165)
      at JoinPoint_r_user_48.invokeNext(JoinPoint_r_user_48.java)
      at JoinPoint_r_user_48.invokeJoinpoint(JoinPoint_r_user_48.java)
      at com.deltel.dtaf.core.services.network.test.irc.Client$ClientAdvisor.Client$ClientAdvisor$user_r_$aop(Client$ClientAdvisor.java)
      at com.deltel.dtaf.core.services.network.test.irc.Client$ClientInstanceAdvisor.Client$ClientAdvisor$user_r_$aop(Client$ClientInstanceAdvisor.java)
      at com.deltel.dtaf.core.services.network.test.irc.Client.user_r_$aop(Client.java)
      at com.deltel.dtaf.core.services.network.test.irc.Client.processData(Client.java:111)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:585)
      at com.deltel.event.flex.FlexSignal.com$deltel$event$flex$FlexSignal$invokeMethod$aop(FlexSignal.java:204)
      at com.deltel.event.flex.FlexSignal$FlexSignalAdvisor.invokeMethod6497039208490023269(FlexSignal$FlexSignalAdvisor.java)
      at com.deltel.event.flex.FlexSignal.invokeMethod(FlexSignal.java)
      at com.deltel.dtaf.api.event.EventSignal.syncExecuteMatch(EventSignal.java:51)
      at com.deltel.dtaf.core.as.event.manager.EventProcessor.fireEvent(EventProcessor.java:64)
      at com.deltel.dtaf.core.as.event.manager.EventProcessor.run(EventProcessor.java:46)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)


      I've done some research, and the problem seems like it might be caused by the fact that the AdvisedPojoHandler object adds a CachedFieldInterceptor to the pojo, before it actually adds the pojo to the Cache. This is a problem beacause CachedFieldInterceptor tries to pull field information out of the cache for a FieldReadInvocation.

        • 1. Re: Threading Bug in PojoCache?
          jason.greene

          If you look at line 165:

           result = pCache_.getObject(new Fqn(fqn_, field.getName()));
          


          The problem is occurring on the lookup of a field, which has a different PojoInstance then the one you are seeing in AdvisedPojoHandler. So this means that the pojo reference for whatever field you were acessing existed before it's actual internal node.

          Are you using optimistic locking? Also are you using transactions?

          -Jason



          • 2. Re: Threading Bug in PojoCache?
            vincent.marquez

            Hey Jason, thanks for taking time to respond to my earlier post. To answer your questions, I'm not using Optimistic Locking, nor transactions.

            When I came back to investigating this bug, I wasn't able to replicate the exact exception, but there most definitely is a race condition and I have a test case to show it. I'm not sure why I can't get the exact same exception, but I have a feeling they are directly related. Do you have any ideas on why I'm getting in the original exception a "null pointer instance"?


            To get the exception I can replicate with an easy test case, run the junit test after inserting a breakpoint in AdvisedPojoHandler at line 128.

            the line should be

             util_.attachInterceptor(obj, advisor, interceptor, observer_);
            


            Run the program, and at any time you wish to cause the exception, simply step over that line to the next one, and wait. This is to simulate one thread reading the data at the exact time another thread could be inserting a pojo into the cache. You shall see when the second thread attempts to access the pojo, an exception is thrown:


            Exception in thread "READERTHREAD" org.jboss.cache.pojo.PojoCacheAlreadyDetachedException: pojo: class org.jboss.cache.pojo.test.Person has possibly been detached remotely. Internal id: /__JBossInternal__/personFqn/_ID_/a232u-oafb98-f18j8tg3-1-f18j8tgi-2
            at org.jboss.cache.pojo.interceptors.dynamic.CacheFieldInterceptor.isPojoDetached(CacheFieldInterceptor.java:235)
            at org.jboss.cache.pojo.interceptors.dynamic.CacheFieldInterceptor.invoke(CacheFieldInterceptor.java:179)
            at org.jboss.cache.pojo.test.JoinPoint_r_age_7.invokeNext(JoinPoint_r_age_7.java)
            at org.jboss.cache.pojo.test.JoinPoint_r_age_7.invokeJoinpoint(JoinPoint_r_age_7.java)
            at org.jboss.cache.pojo.test.Person$PersonAdvisor.Person$PersonAdvisor$age_r_$aop(Person$PersonAdvisor.java)
            at org.jboss.cache.pojo.test.Person$PersonInstanceAdvisor.Person$PersonAdvisor$age_r_$aop(Person$PersonInstanceAdvisor.java)
            at org.jboss.cache.pojo.test.Person.age_r_$aop(Person.java)
            at org.jboss.cache.pojo.test.Person.getAge(Person.java:76)
            at com.deltel.cache.test.ThreadTest$Reader.run(ThreadTest.java:69)
            at java.lang.Thread.run(Unknown Source)




            My unit test I used to show the bug:

            package com.deltel.cache.test;
            
            import org.jboss.cache.config.Configuration;
            import org.jboss.cache.config.Configuration.CacheMode;
            import org.jboss.cache.pojo.test.Person;
            import org.jboss.cache.lock.IsolationLevel;
            import org.jboss.cache.pojo.PojoCache;
            import org.jboss.cache.pojo.PojoCacheFactory;
            
            import EDU.oswego.cs.dl.util.concurrent.Latch;
            
            import junit.framework.Test;
            import junit.framework.TestCase;
            import junit.framework.TestSuite;
            
            public class ThreadTest extends TestCase {
            
             protected PojoCache cache1;
            
             protected Person person = new Person();
            
             protected String personFqn = "personFqn";
            
             private Latch finishedRead = new Latch();
            
             private Latch finishedAdd = new Latch();
            
             public void setUp() throws Exception {
             cache1 = this.fetchCache();
             person.setAge(50);
             }
            
             public void testRun() throws Exception {
            
             Thread t1 = new Thread(new Adder());
             Thread t2 = new Thread(new Reader(),"READERTHREAD");
            
             t1.start();
             t2.start();
            
             this.finishedAdd.acquire();
             this.finishedRead.acquire();
            
             System.out.println("finished without an error");
             }
            
            
             public static Test suite() {
             return new TestSuite(ThreadTest.class);
             }
            
            
             private class Adder implements Runnable {
             public void run() {
             cache1.attach(personFqn, person);
             finishedAdd.release();
             }
             }
            
             private class Reader implements Runnable {
             public void run() {
             for ( int x=0;x<50; x++ ) {
             try {
             Thread.sleep(10000);
             } catch ( InterruptedException e ) {
            
             }
            
             System.out.println("reading the field " + person.getAge());
            
             }
             finishedRead.release();
             }
             }
            
             PojoCache fetchCache() throws Exception {
             PojoCache cache = null;
             Configuration config = new Configuration();
             config.setCacheMode(CacheMode.REPL_SYNC);
             config.setIsolationLevel(IsolationLevel.REPEATABLE_READ);
             config.setLockAcquisitionTimeout(100000);
             config.setFetchInMemoryState(true);
             config.setClusterName("test");
             cache = PojoCacheFactory.createCache(config, false);
             cache.start();
             return cache;
             }
            }
            


            • 3. Re: Threading Bug in PojoCache?
              mvlior

              Hi,

              I've been seeing the same exception in a somewhat different scenario, but perhaps there is a connection, this being the only post mentioning
              "null PojoInstance for fqn"...

              Basically, I'm running a replciated cache on two different JVMs. One attaches a POJO and then detaches it, while the other tries to acces it within a org.jboss.cache.CacheListener#nodeRemoved() method. AFAIK the notifier call is on the same thread.

              The goal was to get a remote notification for POJO creation/deletion.

              Below is the exception that occurs whenever this runs:

              /**
               * @see org.jboss.cache.CacheListener#nodeRemoved(org.jboss.cache.Fqn, boolean, boolean, java.util.Map)
               */
               public void nodeRemoved(Fqn fqn, boolean pre, boolean isLocal, Map<Object, Object> data) {
               log.info("nodeRemoved " + (pre?"pre ":"post ") + (isLocal?"local ":"remote ") + "fqn=" + fqn + " data:" + data);
               if (pre) {
               log.debug("FQN is: " + fqn + ", and the cache is currently " + cache);
               if (fqn.toString().startsWith("__JBossInternal__")) {
               log.trace("(JBoss internal stuff)");
              
               } else {
               // our object !
               Object object = cache.find("/person/test1"); // causes the exception, returns null
               log.info("\nSomething is about to be removed. Something==" + object + '\n');
               }
               }
               }


              Here's the exception, in cotext. If the line "cache.find(....)" is commented-out, everything seems to work just fine.

              2007-05-09 22:03:33,906 INFO [ReplicationDest] (Incoming Thread,192.168.0.112:1170) Modified for removal. Checking data:
              2007-05-09 22:03:33,906 INFO [ReplicationDest] (Incoming Thread,192.168.0.112:1170) Pojo instance is: PI[fqn=null ref=0 class=org.jboss.cache.pojo.test.Person]
              2007-05-09 22:03:33,906 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited post fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
              2007-05-09 22:03:33,906 INFO [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeRemoved pre remote fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3 data:{}
              2007-05-09 22:03:33,921 DEBUG [ReplicationDest] (Incoming Thread,192.168.0.112:1170) FQN is: /__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3, and the cache is currently org.jboss.cache.pojo.impl.PojoCacheImpl cache=/__JBossInternal__ 0
               /person 0
               /test1 0
               /_ID_ 0
               /5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3 0
              /person 0
               /test1 2
               delegate=org.jboss.cache.pojo.impl.PojoCacheDelegate@13043d2 types=0
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited pre fqn=/person/test1
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited post fqn=/person/test1
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited pre fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited post fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited pre fqn=/person/test1
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited post fqn=/person/test1
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited pre fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
              2007-05-09 22:03:33,921 TRACE [ReplicationDest] (Incoming Thread,192.168.0.112:1170) nodeVisited post fqn=/__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
              2007-05-09 22:03:33,984 ERROR [TxInterceptor] (Incoming Thread,192.168.0.112:1170) method invocation failed
              org.jboss.cache.pojo.PojoCacheException: PojoCacheDelegate.getObjectInternal(): null PojoInstance for fqn: /__JBossInternal__/person/test1/_ID_/5c4o034-mm6a9v-f1i7ypgq-1-f1i7ypo4-3
               at org.jboss.cache.pojo.impl.PojoCacheDelegate.getObjectInternal(PojoCacheDelegate.java:338)
               at org.jboss.cache.pojo.impl.PojoCacheDelegate.getObject(PojoCacheDelegate.java:106)
               at org.jboss.cache.pojo.impl.PojoCacheImpl.getObject(PojoCacheImpl.java:211)
               at org.jboss.cache.pojo.impl.PojoCacheImpl.org$jboss$cache$pojo$impl$PojoCacheImpl$find$aop(PojoCacheImpl.java:200)
               at org.jboss.cache.pojo.impl.PojoCacheImpl$JoinPoint_find_N_7063709169143275953.dispatch(PojoCacheImpl$JoinPoint_find_N_7063709169143275953.java)
               at org.jboss.cache.pojo.impl.JoinPoint_find_N_7063709169143275953_2.invokeNext(JoinPoint_find_N_7063709169143275953_2.java)
               at org.jboss.cache.pojo.interceptors.CheckIdInterceptor.invoke(CheckIdInterceptor.java:32)
               at org.jboss.cache.pojo.impl.JoinPoint_find_N_7063709169143275953_2.invokeNext(JoinPoint_find_N_7063709169143275953_2.java)
               at org.jboss.cache.pojo.interceptors.PojoBeginInterceptor.invoke(PojoBeginInterceptor.java:54)
               at org.jboss.cache.pojo.impl.JoinPoint_find_N_7063709169143275953_2.invokeNext(JoinPoint_find_N_7063709169143275953_2.java)
               at org.jboss.cache.pojo.impl.JoinPoint_find_N_7063709169143275953_2.invokeJoinpoint(JoinPoint_find_N_7063709169143275953_2.java)
               at org.jboss.cache.pojo.impl.PojoCacheImpl$PojoCacheImplAdvisor.find_N_7063709169143275953(PojoCacheImpl$PojoCacheImplAdvisor.java)
               at org.jboss.cache.pojo.impl.PojoCacheImpl$PojoCacheImplInstanceAdvisor.find_N_7063709169143275953(PojoCacheImpl$PojoCacheImplInstanceAdvisor.java)
               at org.jboss.cache.pojo.impl.PojoCacheImpl.find(PojoCacheImpl.java)
               at org.jboss.cache.pojo.impl.PojoCacheImpl.find(PojoCacheImpl.java:187)
               at mailvision.ReplicationDest.nodeRemoved(ReplicationDest.java:150)
               at org.jboss.cache.notifications.Notifier.notifyNodeRemoved(Notifier.java:233)
               at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2323)
               at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2257)
               at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2243)
               at org.jboss.cache.CacheImpl._remove(CacheImpl.java:2237)
               at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
               at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
               at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
               at java.lang.reflect.Method.invoke(Method.java:585)
               at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
               at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:33)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:202)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:34)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:22)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:497)
               at org.jboss.cache.interceptors.TxInterceptor.handlePessimisticPrepare(TxInterceptor.java:391)
               at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:249)
               at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:97)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:168)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:75)
               at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:66)
               at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3752)
               at org.jboss.cache.CacheImpl._replicate(CacheImpl.java:2675)
               at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
               at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
               at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
               at java.lang.reflect.Method.invoke(Method.java:585)
               at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
               at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:92)
               at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:624)
               at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:533)
               at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:365)
               at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:721)
               at org.jgroups.JChannel.up(JChannel.java:1050)
               at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:326)
               at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:509)
               at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:246)
               at org.jgroups.protocols.FRAG2.up(FRAG2.java:197)
               at org.jgroups.protocols.pbcast.GMS.up(GMS.java:717)
               at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:226)
               at org.jgroups.protocols.UNICAST.up(UNICAST.java:231)
               at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:692)
               at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:527)
               at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:154)
               at org.jgroups.protocols.FD.up(FD.java:328)
               at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:301)
               at org.jgroups.protocols.MERGE2.up(MERGE2.java:145)
               at org.jgroups.protocols.Discovery.up(Discovery.java:224)
               at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1541)
               at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1495)
               at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
               at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
               at java.lang.Thread.run(Thread.java:595)



              What do you think ?

              Thanks in advance!

              Lior Neuman
              R&D Team,
              MailVision LTD.


              • 4. Re: Threading Bug in PojoCache?
                jason.greene

                 

                "vincent.marquez" wrote:
                Hey Jason, thanks for taking time to respond to my earlier post. To answer your questions, I'm not using Optimistic Locking, nor transactions.

                When I came back to investigating this bug, I wasn't able to replicate the exact exception, but there most definitely is a race condition and I have a test case to show it. I'm not sure why I can't get the exact same exception, but I have a feeling they are directly related. Do you have any ideas on why I'm getting in the original exception a "null pointer instance"?


                There was a thread safety problem that I fixed in CR1 that might have caused both issues. Are you still seeing it?

                -Jason

                • 5. Re: Threading Bug in PojoCache?
                  jason.greene

                   

                  "mvlior" wrote:
                  Hi,

                  I've been seeing the same exception in a somewhat different scenario, but perhaps there is a connection, this being the only post mentioning
                  "null PojoInstance for fqn"...

                  Basically, I'm running a replciated cache on two different JVMs. One attaches a POJO and then detaches it, while the other tries to acces it within a org.jboss.cache.CacheListener#nodeRemoved() method. AFAIK the notifier call is on the same thread.

                  The goal was to get a remote notification for POJO creation/deletion.


                  This is a timing problem. When a node is attached an internal node is created and the name you pass is used to create a reference node. When a node is removed the internal node is deleted first, so by the time your notification is received its not there which causes find() to fail.

                  2.0.0.GA will have remote pojo notification support, so I would recommend switching to that when its available.

                  -Jason