Extremely rare (but real) un-marshall Exception - why?

[cotton.ben]

The following exception appears extremely rarely, but it does occasionally appear.  What causes it?

Caused by: java.io.InvalidObjectException: Attempt to read a backreference with an invalid ID (relative near -1)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:253)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:153)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:139)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Attributes$AttributesExternalizer.readObject(Attributes.java:81)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Attributes$AttributesExternalizer.readObject(Attributes.java:1)

Some background:

I have a test that I run on an Inifinspan Grid (3 JVM nodes, DIST_SYNC) that includes several thousand operations on a piece of un-modified  application code.  The Test code basically does 1000s of put()/get() operations on an Object graph ( that at various points of its run-time includes an object instance of  an  'Attributes' Class within its heirarchy).  NOTE = All non-primitive participants in this Object graph implement  org.infinispan.marshall.Externalizer so that the full Object graph may at all-points realize the merits of JBoss Marshalling Protocol as their Serializable provider.

For completeness, attached is the full Attributes.java source code.

Again, this code is never modified and is called thousands of time from Test code.  Only very, very rarely does the Exception appear.  ANy ideas on what run-time conditions cause this Exception? Any ideas on how to remedy the situation show that this Exception never appears?

Many thanks for any consideration to help me figure this out!

Ben

@SerializeWith(Attributes.AttributesExternalizer.class)

public class Attributes {

    public Attributes() {   

    }

    public Attributes(List<Attribute> readObject) {

        this.attribute = readObject;

    }

    public static class AttributesExternalizer implements Externalizer<Attributes> {

        private static final long serialVersionUID = 1L;

        public AttributesExternalizer() {

        }

        @Override

        public Attributes readObject(ObjectInput input) throws IOException, ClassNotFoundException {

            return new Attributes((List<Attribute>) input.readObject());  //this line appears on Exception stack trace

        }

        @Override

        public void writeObject(ObjectOutput output, Attributes al) throws  IOException  {

            output.writeObject(al);

        }

    }

    public List<Attribute> getAttribute() {

        if (attribute == null) {

            attribute = new ArrayList<Attribute>();

        }

        return this.attribute;

    }

}

[cotton.ben]

Sorry.  My cut-paste of the .java was not complete.

@SerializeWith(Attributes.AttributesExternalizer.class)

public class Attributes {

    protected List<Attribute> attribute;

    public Attributes() {   

    }

    public Attributes(List<Attribute> readObject) {

        this.attribute = readObject;

    }

    public static class AttributesExternalizer implements Externalizer<Attributes> {

        private static final long serialVersionUID = 1L;

        public AttributesExternalizer() {

        }

        @Override

        public Attributes readObject(ObjectInput input) throws IOException, ClassNotFoundException {

            return new Attributes((List<Attribute>) input.readObject());  //this line appears on Exception stack trace

        }

        @Override

        public void writeObject(ObjectOutput output, Attributes al) throws  IOException  {

            output.writeObject(al);

        }

    }

    public List<Attribute> getAttribute() {

        if (attribute == null) {

            attribute = new ArrayList<Attribute>();

        }

        return this.attribute;

    }

}

[dmlloyd]

In what context does this error appear? Is this an EJB invocation, an Infinispan-stored object, or something else?

[dmlloyd]

Ah, Infinispan forum, should have looked.

Can you post the complete stack trace?  I suspect that the usual culprit, the Infinispan ObjectTable, is the most likely cause, but I'll reserve judgement pending more information.

[cotton.ben]

Here you go.

2013-05-24 14:28:28,581 (InvocationContextInterceptor.java:123) ERROR org.infinispan.interceptors.InvocationContextInterceptor - ISPN000136: Exe

cution error

org.infinispan.CacheException: Problems invoking command.

        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:148)

        at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:447)

        at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:354)

        at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:230)

        at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:556)

        at org.jgroups.JChannel.up(JChannel.java:716)

        at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)

        at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)

        at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)

        at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)

        at org.jgroups.protocols.pbcast.GMS.up(GMS.java:881)

        at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)

        at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:618)

        at org.jgroups.protocols.UNICAST.up(UNICAST.java:317)

        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:597)

        at org.jgroups.protocols.BARRIER.up(BARRIER.java:102)

        at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:167)

        at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:284)

        at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)

        at org.jgroups.protocols.Discovery.up(Discovery.java:354)

        at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)

        at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1709)

        at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1691)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

        at java.lang.Thread.run(Thread.java:722)

Caused by: java.io.InvalidObjectException: Attempt to read a backreference with an invalid ID (relative near -1)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:253)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:153)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:139)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Attributes$AttributesExternalizer.readObject(Attributes.java:81)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Attributes$AttributesExternalizer.readObject(Attributes.java:1)

        at org.infinispan.marshall.jboss.JBossExternalizerAdapter.createExternal(JBossExternalizerAdapter.java:54)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1273)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:272)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:153)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:139)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimension$DimensionExternalizer.readObject(Dimension.java:154)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimension$DimensionExternalizer.readObject(Dimension.java:1)

        at org.infinispan.marshall.jboss.JBossExternalizerAdapter.createExternal(JBossExternalizerAdapter.java:54)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1273)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:272)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:37)

        at org.infinispan.marshall.exts.ArrayListExternalizer.readObject(ArrayListExternalizer.java:57)

        at org.infinispan.marshall.exts.ArrayListExternalizer.readObject(ArrayListExternalizer.java:45)

        at org.infinispan.marshall.jboss.ExternalizerTable$ExternalizerAdapter.readObject(ExternalizerTable.java:401)

        at org.infinispan.marshall.jboss.ExternalizerTable.readObject(ExternalizerTable.java:289)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:351)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:153)

        at org.jboss.marshalling.river.BlockUnmarshaller.readObject(BlockUnmarshaller.java:139)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimensions$DimensionsExternalizer.readObject(Dimensions.java:83)

        at com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimensions$DimensionsExternalizer.readObject(Dimensions.java:1)

        at org.infinispan.marshall.jboss.JBossExternalizerAdapter.createExternal(JBossExternalizerAdapter.java:54)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1273)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:272)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:37)

        at org.infinispan.marshall.exts.ReplicableCommandExternalizer.readParameters(ReplicableCommandExternalizer.java:118)

        at org.infinispan.marshall.exts.ReplicableCommandExternalizer.readObject(ReplicableCommandExternalizer.java:106)

        at org.infinispan.marshall.exts.ReplicableCommandExternalizer.readObject(ReplicableCommandExternalizer.java:57)

        at org.infinispan.marshall.jboss.ExternalizerTable$ExternalizerAdapter.readObject(ExternalizerTable.java:401)

        at org.infinispan.marshall.jboss.ExternalizerTable.readObject(ExternalizerTable.java:289)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:351)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:37)

        at org.infinispan.marshall.exts.ReplicableCommandExternalizer.readParameters(ReplicableCommandExternalizer.java:118)

        at org.infinispan.marshall.exts.CacheRpcCommandExternalizer.readObject(CacheRpcCommandExternalizer.java:165)

        at org.infinispan.marshall.exts.CacheRpcCommandExternalizer.readObject(CacheRpcCommandExternalizer.java:68)

        at org.infinispan.marshall.jboss.ExternalizerTable$ExternalizerAdapter.readObject(ExternalizerTable.java:401)

        at org.infinispan.marshall.jboss.ExternalizerTable.readObject(ExternalizerTable.java:289)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:351)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:37)

        at org.infinispan.marshall.jboss.AbstractJBossMarshaller.objectFromObjectStream(AbstractJBossMarshaller.java:119)

        at org.infinispan.marshall.VersionAwareMarshaller.objectFromByteBuffer(VersionAwareMarshaller.java:115)

        at org.infinispan.marshall.AbstractDelegatingMarshaller.objectFromByteBuffer(AbstractDelegatingMarshaller.java:79)

        at org.infinispan.remoting.transport.jgroups.MarshallerAdapter.objectFromBuffer(MarshallerAdapter.java:50)

        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:138)

        ... 25 more

Caused by: an exception which occurred:

        in object of type com.jpmorgan.lri.cs.ae.snapshot.config.generated.Attributes

        in object of type com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimension

        in object of type com.jpmorgan.lri.cs.ae.snapshot.config.generated.Dimensions

[dmlloyd]

The reason I suspect the Infinispan ObjectTable is because the marshaller code itself is highly deterministic.  Whenever a sporadic problem has appeared, historically, it has always been in the context of Infinispan because it layers on more dynamic pieces to do things like maintaining object and class tables for compact serialization.

[cotton.ben]

So would you recommend that I open a bug-fix JIRA request with the Infinispan team?   Unfortunately, even if this problem is no more sporadic than 1 in 1,000 it is still a concerning delinquency.

[sannegrinovero]

On a different project using Infinispan (Hibernate) I've had some occasional failures in the testsuite which seem to have similar simptoms. Our testsuite is run in many different platforms, but I noticed that all failures happened on Windows only. Are you using Windows where you see these failures?

[cotton.ben]

Actually, we have seen this failure on Linux too.   Again, it is exceedingly rare, but it still concerns us.  It seemingly only happens at 'readObject' points for our most complex Object graph -- which we call 'Dimensions'.  We've never seen it happen on our less complex hierarchical Object graphs.  We've never seen it happen when our Serializable/Externalizable provider is something other than JBoss Marshall Externalizer<T>  (but of course we choose that provider for all our Object graphs hosted on Infinispan).

Do you think there may be merit to designing/scheming/(hacking?) a 'lets survive this Exception!' capability  - that could possibly call for a 'just re readObject graph' when this Exception is encountered?  That of course is not a solution - just a survival tactic.  

That it is so exceedingly rare (for such a frequently successfully executed operation!) leads me to believe that any insights to the true root cause of this malady will require some serious debug committment.

Does David Lloyd's comment ...

historically, it has always been in the context of Infinispan because it layers on more dynamic pieces to do things like maintaining object and class tables for compact serialization.

... suggest to you that Infinispan's tactics to bridge to the capability potentially introduces a risk?  That can be OK and survivable if we are given a way to manage a tolerance for where we want to be on this "capability vs. risk" curve. 

Thanks everybody  for your always excellent interactive support,

Ben

[pruivo]

Hi Ben,

I'm not an expert in this are but I think you have something wrong in your externalizer:

Ben Cotton wrote:

        @Override

        public Attributes readObject(ObjectInput input) throws IOException, ClassNotFoundException {

            return new Attributes((List<Attribute>) input.readObject());  //this line appears on Exception stack trace

        }

        @Override

        public void writeObject(ObjectOutput output, Attributes al) throws  IOException  {

            output.writeObject(al);

        }

I don't know if you've noticed, but in writeObject() you are writing for an object of class Attributes and in your readObject(), you are reading an object of class List<Attributes>. I was expecting to having a ClassCastException in this scenario...

Also, in writeObject(), you are writing for the ObjectOutput the class Attributes and the class is serialized by the AttributesExternalizer. I think that will create a infinite loop because it will invoke the writeObject() again.

A suggestion: I would try to change your writeObject() to: output.writeObject(al.attribute); in order to serialize the List<Attribute>...

BTW, could someone please comment my two sentences above?

Cheers,

Pedro

[cotton.ben]

Hi Ben,

I'm not an expert in this are but I think you have something wrong in your externalizer:

Thank you Pedro.

[sannegrinovero]

Hi Ben, did Pedro's suggestion solve your problem?

I'm puzzled on why this exception would not happen consistently?

[cotton.ben]

Hi Sanne,

We are now quite  sure that Pedro's suggestion did indeed fix the problem.  Millions of test trials exercising this new code, we can't get this exception to appear even once.  AWESOME.

Moreover, we've attached a distributed debugger to an Externalizer session to confirm that what we get() is what we put()  .... and yes everything checks out perfectly now.

But, yes, I'm puzzled too!   What on earth were we getting before when the old code did not throw an exception? A little scary.

SUGGESTION:  The end-user could benifit greatly from a code generation tool that could help them un-wind complex Object graph hiearchies into a corresponding hierarchy of  AdvancedExternalizer<T> implementations .... Doing this by hand is not for the faint of heart!

As always, thanks for your stellar support.

[cotton.ben]

HI everybody,

just an FYI.   To accommodate our (perverse) sense of wanting to understand 'what the heck was causing that?'   We found a way to re-produce the mysterious "java.io.InvalidObjectException: Attempt to read a backreference with an invalid ID (relative near -1)"  with great frequency.   To get this to reproduce frequently we "broke" all the points in our complex Object graph that behave like our 'Attributes' object.

Specifically, what we did was we purposefully "broke everything everywhere" to look like this:

@Override
        public void writeObject(ObjectOutput output, Attributes al) throws  IOException  {
            output.writeObject(al);    //mistake!  Pedro correctly advised to use    al.attribue
            //output.writeObject(al.attribute);     //correct.  as per Pedro @infinispan team.
       }

Now we are able to get lots of occurrennces of "java.io.InvalidObjectException: Attempt to read a backreference with an invalid ID (relative near -1)" to appear whenever we churn the tests. Interestingly, there are still lots of iterations of the tests where this code just flys on by with no exception at all.  But of course, the object written at that point in the object graph could not possibly be correct.  Silent and Deadly.

Possible moral of the story?  Having an end-user manually implemement an Object graph hierarchy of AdvancedExternalizer<T> is a real burden for the end-user!  Some kind of tool to help us have this generated for us would be very welcome.

Thanks again for all your help.