Ice.MarshalException problem w/ IceStorm.

[smandy]

Hi All,

I've got a gui app on windows subscribing via icestorm to a linux server (both java 1.6.0_21 + Ice-3.4.0 ) and I'm intermittently starting to see throw Ice.MarshalExceptions

A pared down version of the slice definitions I'm using is...

struct BatchUpdate {
String2Stats stats1;
String2Stats stats2;
String2State statesById;
};


interface ServerListener extends Pingable
{
["ami"] void onBatchUpdate( BatchUpdate batch );
};

Where string2stats/string2state are dictionaries of updated items that are to be passed by value.

Getting exceptions in the icestorm stderr of the form....

- 03/28/11 16:26:18.433 PermIceBox-IceStorm: Topic: praxis.server.image: subscribeAndGetPublisher: e172d957-0e0a-4143-b517-f28bbff3f3bb QoS:
-- 03/28/11 16:27:32.680 PermIceBox-IceStorm: Subscriber: 0x2aaab4000ed0 transition from online to error
-- 03/28/11 16:27:32.680 PermIceBox-IceStorm: Subscriber: 0x2aaab4000ed0 e172d957-0e0a-4143-b517-f28bbff3f3bb: subscriber errored out: OutgoingAsync.cpp:680: Ice::UnknownLocalException:
unknown local exception:
Ice::MarshalException
Ice.MarshalException
reason = (null)
at IceInternal.BasicStream.typeToClass(BasicStream.ja va:2314)
at IceInternal.BasicStream.findClass(BasicStream.java :2234)
at IceInternal.BasicStream.loadObjectFactory(BasicStr eam.java:2101)
at IceInternal.BasicStream.readObject(BasicStream.jav a:1470)
at IceInternal.BasicStream.readPendingObjects(BasicSt ream.java:1666)
at praxis.trading._ServerListenerDisp.___onBatchUpdat e(_ServerListenerDisp.java:328)
at praxis.trading._ServerListenerDisp.__dispatch(_Ser verListenerDisp.java:421)
at IceInternal.Incoming.invoke(Incoming.java:159)
at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)
at Ice.ConnectionI.dispatch(ConnectionI.java:1199)
at Ice.ConnectionI.message(ConnectionI.java:1154)
at IceInternal.ThreadPool.run(ThreadPool.java:302)
at IceInternal.ThreadPool.access$300(ThreadPool.java: 12)
at IceInternal.ThreadPool$EventHandlerThread.run(Thre adPool.java:644)
at java.lang.Thread.run(Unknown Source)
retry: 0/0
-- 03/28/11 16:27:32.690 PermIceBox-IceStorm: Subscriber: 0x6317000 transition from online to error
-- 03/28/11 16:27:32.690 PermIceBox-IceStorm: Subscriber: 0x6317000 67b68c0c-770f-4fee-80b0-64bb40519237: subscriber errored out: OutgoingAsync.cpp:680: Ice::UnknownLocalException:
unknown local exception:
Ice::MarshalException
Ice.MarshalException
reason = (null)
at IceInternal.BasicStream.typeToClass(BasicStream.ja va:2314)
at IceInternal.BasicStream.findClass(BasicStream.java :2234)
at IceInternal.BasicStream.loadObjectFactory(BasicStr eam.java:2101)
at IceInternal.BasicStream.readObject(BasicStream.jav a:1470)
at IceInternal.BasicStream.readPendingObjects(BasicSt ream.java:1666)
at praxis.trading._ServerListenerDisp.___onBatchUpdat e(_ServerListenerDisp.java:328)
at praxis.trading._ServerListenerDisp.__dispatch(_Ser verListenerDisp.java:421)
at IceInternal.Incoming.invoke(Incoming.java:159)
at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)
at Ice.ConnectionI.dispatch(ConnectionI.java:1199)
at Ice.ConnectionI.message(ConnectionI.java:1154)
at IceInternal.ThreadPool.run(ThreadPool.java:302)
at IceInternal.ThreadPool.access$300(ThreadPool.java: 12)
at IceInternal.ThreadPool$EventHandlerThread.run(Thre adPool.java:644)
at java.lang.Thread.run(Unknown Source)
retry: 0/0

On the server side I'm using a batched oneway proxy to package up a number of updates to cause less strain on the network and the gui.

I haven't taken too much ( i.e. *any* care about considerations like the Message ordering + retry counts in the QoS parameter I pass to icestorm, so my subscriptions are getting reaped by icestorm as soon as an error occurs). Even though I haven't been paying much attention to these issues, I'd have thougt it would hit me in my application logic, not in the ice runtime.

On the gui side I'm using quite a vanilla subscription. The gui runs happily for several hundred messages but it feels that it's when the message rate spikes is when these exceptions are thrown.

I'm at a bit of a loss though as if the gui is being inundated I would have expected, say, connection closed , memory limit, maybe out of memory exception to be thrown, so I'm confused as to why it's a MarshalException that's being thrown. Are there any known cases when MarshalException can mask something more pernicious?

I'll keep looking in to this but if anyone has any helpful advice as to where I should be looking I'd be grateful. ( Can setting messagesize max to disparate values in client/server/icestorm cause something like this for example?!, At the moment server+icestorm have 4M set, gui uses 2M for ... erm... largely historic purposes). Having said that though I'd have though if this were the problem I'd be getting a messagesize max, not a MarshalException.

Another sanity check I've performed was to ensure the client + server are using the same ice runtime jar and same compiled slice definitions. Were this not the case though I'd have expected almost immediate failure versus failure after a few minutes.

Regards,

Andrew.

[mes]

Hi Andrew,

That is indeed a strange problem.

The stack trace in the exception is useful but also puzzling. Looking at the source for BasicStream.java from Ice 3.4.0, the exception occurs here:

    private String
    typeToClass(String id)
    {
        if(!id.startsWith("::"))
        {
            throw new Ice.MarshalException();
        }

It's unfortunate that we didn't include more information in this exception (probably have myself to blame for that one).

If you're comfortable building Ice for Java from source, I suggest downloading the source archive and modifying the code above to include the value of id in the exception message.

The fact that this Slice type ID is missing the leading double colons is a big red flag. It most likely means the message is malformed, and the leading cause of this is mismatched Slice definitions between sender and receiver.

Also keep in mind that we only provide free support here for the most recent Ice release, so I suggest upgrading to Ice 3.4.1 as soon as possible.

Regards,
Mark

[smandy]

I'll do that marc. Thanks for quick reply....

Hmm.... I just realised. I had to rebuild my machine recently, and it's possible. ( In fact it's almost certainly the case), that I've already been generating code with the 3.4.1 slice2java compiler which I subsequently have been running against the 3.4.0 runtime. Would this have caused any problems?



The versions I've been using ....

slice2java 3.4.1
java runtime 3.4.0
icestorm 3.4.0

I remember in the 3.4.1 release notes I read the two were binary compatible so I didn't give it much thought but can I assume i have a greencard to mix+match runtimes with code-generators?

Thanks,

A.

[bernard]

Hi Andy,

'Binary compatibility' allows you to replace your Ice 3.4.0 libraries (jars...) by Ice 3.4.1 libraries without rebuilding anything. As a result, the code generated by slice2java 3.4.0 is guaranteed to work with the Ice 3.4.x runtime.

There is however no guarantee the other way around: if you're developing with slice2java 3.4.1, your runtime version has to be 3.4.1 (or 3.4.2, 3.4.3...).

Best regards,
Bernard

[smandy]

Thanks bernard, got it.

I've run the slice files for my app through the 3.4.1 and 3.4.0 slice2java compilers and the only differences I can see are slight differences in the equality comparisons that are generated. Can't tell if that could have caused the malformed message problems or not. I'll obviously get all the runtimes up to 3.4.1 toot-sweet but I was just trying to determine if this could have been enough to account for my problem.

Anyway I've compiled 3.4.1 with a more informative exception in the 'typeToClass' method of basic stream so we shall see what comes out of that tomorrow...

Thanks a lot,

A.

[smandy]

Hi guys,

Well I've upgraded to Ice 3.4.1 and am still seeing a problem. ( Okay I confess my Icestorm instance is still 3.4.0 but from what I understand he should just be obliviously passing my messages from publishers to subscribers right?).

I've made the change suggested in BasicStream ( here's my modification).

  private String
    typeToClass(String id)
    {
        if(!id.startsWith("::"))
        {
            throw new Ice.MarshalException("Malformed id '" + id + "'");
        }

        StringBuilder buf = new StringBuilder(id.length());

        int start = 2;
        boolean done = false;
        while(!done)

I see the following tracebacks. ( This is from icestorm log, two guis are connected so have included both tracebacks to indicate that they both throw the same exception. I've pasted from emacs so the binary characters in the exception string have been suitable formatted).

Any ideas? Is there anything else I can try? I've verified both the runtime jar and the jar containing my compiled slice definitions are identical. I've enclosed two stacktraces, one is a rather boring empty string, but the second looks a little more interesting...

I've also written a separate bare-bones commandline subscriber that does nothing other than print out which methods are being invoked, and it throws the same exceptions as the gui.

Thanks,

Andrew.

   unknown local exception:
   Ice::MarshalException
   Ice.MarshalException^M
       reason = "Malformed id ''"^M
        at IceInternal.BasicStream.typeToClass(BasicStream.java:2320)^M
        at IceInternal.BasicStream.findClass(BasicStream.java:2240)^M
        at IceInternal.BasicStream.loadObjectFactory(BasicStream.java:2107)^M
        at IceInternal.BasicStream.readObject(BasicStream.java:1476)^M
        at praxis.trading.String2StateHelper.read(String2StateHelper.java:53)^M
        at praxis.trading.BatchUpdate.__read(BatchUpdate.java:135)^M
        at praxis.trading._ServerListenerDisp.___onBatchUpdate(_ServerListenerDisp.java:327)^M
        at praxis.trading._ServerListenerDisp.__dispatch(_ServerListenerDisp.java:421)^M
        at IceInternal.Incoming.invoke(Incoming.java:159)^M
        at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)^M
        at Ice.ConnectionI.dispatch(ConnectionI.java:1199)^M
        at Ice.ConnectionI$1.run(ConnectionI.java:1140)^M
        at java.awt.event.InvocationEvent.dispatch(Unknown Source)^M
        at java.awt.EventQueue.dispatchEvent(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.run(Unknown Source)^M
    retry: 0/0
-- 03/30/11 14:10:31.702 PermIceBox-IceStorm: Subscriber: 0x2aaab0007530 transition from online to error
-- 03/30/11 14:10:31.702 PermIceBox-IceStorm: Subscriber: 0x2aaab0007530 6cde0cb9-d522-474e-8b56-05317c849174: subscriber errored out: Outgoi\
ngAsync.cpp:680: Ice::UnknownLocalException:
   unknown local exception:
   Ice::MarshalException
   Ice.MarshalException^M
       reason = "Malformed id ''"^M
        at IceInternal.BasicStream.typeToClass(BasicStream.java:2320)^M
        at IceInternal.BasicStream.findClass(BasicStream.java:2240)^M
        at IceInternal.BasicStream.loadObjectFactory(BasicStream.java:2107)^M
        at IceInternal.BasicStream.readObject(BasicStream.java:1476)^M
        at praxis.trading.String2StateHelper.read(String2StateHelper.java:53)^M
        at praxis.trading.BatchUpdate.__read(BatchUpdate.java:135)^M
        at praxis.trading._ServerListenerDisp.___onBatchUpdate(_ServerListenerDisp.java:327)^M
        at praxis.trading._ServerListenerDisp.__dispatch(_ServerListenerDisp.java:421)^M
        at IceInternal.Incoming.invoke(Incoming.java:159)^M
        at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)^M
        at Ice.ConnectionI.dispatch(ConnectionI.java:1199)^M
        at Ice.ConnectionI$1.run(ConnectionI.java:1140)^M
        at java.awt.event.InvocationEvent.dispatch(Unknown Source)^M
        at java.awt.EventQueue.dispatchEvent(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.run(Unknown Source)^M
    retry: 0/0




   Ice::MarshalException
   Ice.MarshalException^M
       reason = "Malformed id '^A^@^@^@^@^@^@^@^M::Ice::Object^E^@^@^@^@&^@^@^@^A^A^\^@^@^@\357\277\275\357\277\275\357\277\275\357\277\275^B^@\
^@^@^@^@^@^@^@\357\277\275I8@^A^@^@^@^@^@^@^A^B^E^@^@^@'"^M
        at IceInternal.BasicStream.typeToClass(BasicStream.java:2320)^M
        at IceInternal.BasicStream.findClass(BasicStream.java:2240)^M
        at IceInternal.BasicStream.loadObjectFactory(BasicStream.java:2107)^M
        at IceInternal.BasicStream.readObject(BasicStream.java:1476)^M
        at praxis.trading.String2StateHelper.read(String2StateHelper.java:53)^M
        at praxis.trading.BatchUpdate.__read(BatchUpdate.java:135)^M
        at praxis.trading._ServerListenerDisp.___onBatchUpdate(_ServerListenerDisp.java:327)^M
        at praxis.trading._ServerListenerDisp.__dispatch(_ServerListenerDisp.java:421)^M
        at IceInternal.Incoming.invoke(Incoming.java:159)^M
        at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)^M
        at Ice.ConnectionI.dispatch(ConnectionI.java:1199)^M
        at Ice.ConnectionI$1.run(ConnectionI.java:1140)^M
        at java.awt.event.InvocationEvent.dispatch(Unknown Source)^M
        at java.awt.EventQueue.dispatchEvent(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.pumpEvents(Unknown Source)^M
        at java.awt.EventDispatchThread.run(Unknown Source)^M
    retry: 0/0
-- 03/30/11 14:30:25.423 PermIceBox-IceStorm: Subscriber: 0x5008d60 transition from online to error
-- 03/30/11 14:30:25.423 PermIceBox-IceStorm: Subscriber: 0x5008d60 44a237bc-9cae-496a-aee2-69b28b57a9c7: subscriber errored out: OutgoingAsy\
nc.cpp:680: Ice::UnknownLocalException:
   unknown local exception:
   Ice::MarshalException
   Ice.MarshalException^M
       reason = "Malformed id '^A^@^@^@^@^@^@^@^M::Ice::Object^E^@^@^@^@&^@^@^@^A^A^\^@^@^@\357\277\275\357\277\275\357\277\275\357\277\275^B^@\
^@^@^@^@^@^@^@\357\277\275I8@^A^@^@^@^@^@^@^A^B^E^@^@^@'"^M
        at IceInternal.BasicStream.typeToClass(BasicStream.java:2320)^M
        at IceInternal.BasicStream.findClass(BasicStream.java:2240)^M
        at IceInternal.BasicStream.loadObjectFactory(BasicStream.java:2107)^M
        at IceInternal.BasicStream.readObject(BasicStream.java:1476)^M
        at praxis.trading.String2StateHelper.read(String2StateHelper.java:53)^M
        at praxis.trading.BatchUpdate.__read(BatchUpdate.java:126)^M
        at praxis.trading._ServerListenerDisp.___onBatchUpdate(_ServerListenerDisp.java:327)^M
        at praxis.trading._ServerListenerDisp.__dispatch(_ServerListenerDisp.java:421)^M
        at IceInternal.Incoming.invoke(Incoming.java:159)^M
        at Ice.ConnectionI.invokeAll(ConnectionI.java:2312)^M
        at Ice.ConnectionI.dispatch(ConnectionI.java:1199)^M
        at Ice.ConnectionI$1.run(ConnectionI.java:1140)^M
        at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)^M
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:597)^M
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:269)^M
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:184)^M
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:174)^M
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:169)^M
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:161)^M
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:122)^M
    retry: 0/0

[mes]

Hi Andrew,

The only suggestion I can make at this point is for you to provide a small, self-contained example that we can use to reproduce the problem.

Regards,
Mark

[smandy]

Okay will try :-)

[smandy]

Hi guys,

Reading and re-reading my code I realised I was incorrectly publishing one of the dictionaries to ice ( 'publishing' in the Java memory model sense, that is). I was assembling the dictionary in one thread and passing it off to another for submission to ice. Although the reference was being correctly published to the ice thread, it was a reference to a hashtable, for which there are no 'happens-before' guarantees, thus all bets are off as to the ice thread seeing correct data. Replacing hashtable with its concurrent equivalent seems to have fixed the problem.

Just to understand, although I created an invalid message icestorm was quite happy to pass it on to subscribers, is this because the invocations would have been wrapped up in an encapsulation, and as such, icestorm would neither know nor care that he was passing on an invalid message?

Thanks for your help on this, apologies it turned out to be a bit of red herring :-(

Andy.

[mes]

Reading and re-reading my code I realised I was incorrectly publishing one of the dictionaries to ice ( 'publishing' in the Java memory model sense, that is). I was assembling the dictionary in one thread and passing it off to another for submission to ice. Although the reference was being correctly published to the ice thread, it was a reference to a hashtable, for which there are no 'happens-before' guarantees, thus all bets are off as to the ice thread seeing correct data. Replacing hashtable with its concurrent equivalent seems to have fixed the problem.

Yes, a servant must be careful not to alter objects that it returns to Ice. We discuss this issue in Section 32.10.6:

http://www.zeroc.com/doc/Ice-3.4.1-I...ver.33.10.html

If this is not the situation you're referring to, please provide more details.

Just to understand, although I created an invalid message icestorm was quite happy to pass it on to subscribers, is this because the invocations would have been wrapped up in an encapsulation, and as such, icestorm would neither know nor care that he was passing on an invalid message?

That's correct. IceStorm receives the message as a blob of bytes and doesn't attempt to decode them; it simply forwards the message on to subscribers.

Regards,
Mark

[smandy]

Hi Mes, Sorry should have said hash*map* not hashtable in my previous post.

As far as I can tell I failed to ensure that the changes I made to the hashmap on my 'writing' thread were visible to my 'reading' thread. (i.e. ice). - I didn't use either a synchronized block or a volatile variable to ensure a 'happens-before' relationship between my writes on one thread and reads of the map by ice. ( This is culled from my vague memories of JCIP and a quick re-glancing of chapter 17 of the java language spec :-) ).

If this is the case I believe the reading thread ( i.e. ice, could have seen an inconsistent copy of the map). I think this may have messed up the code used to marshall the map in question, say for this guy...

public final class String2StateHelper
{
    public static void
    write(IceInternal.BasicStream __os, java.util.Map<java.lang.String, State> __v)
    {
        if(__v == null)
        {
            __os.writeSize(0);
        }
        else
        {
            __os.writeSize(__v.size());
            for(java.util.Map.Entry<java.lang.String, State> __e : __v.entrySet())
            {
                __os.writeString(__e.getKey());
                __os.writeObject(__e.getValue());
            }
        }
    }

... there's no guarantee that ice sees a consistent size and entryset. This wouldn't have necessarily have caused a blowup during marshalling but at the receiving end the corresponding read method would have tried to unmarshall either too many or too few key/value pairs, hence corruption on the reading side.

This is what I suspect has happened, however I can't conclusively prove this. But it's plausible enough that I'm prepared to let it go at that. I doubt very much there's a bug in ice :-) All I'm aware of is that I replaced the Hashmap with its concurrent equivalent and a problem hasn't recurred. To give perspective I was performing this operation every 100ms and it blew up approximately every 10 minutes, with the concurrent hashmap in place the same app has run without a problem most of today. I'm happy enough to draw a line under it at that but if you want me to try anything else let me know ... happy to :-)

[mes]

Right, concurrently modifying data that Ice is still in the process of marshaling is definitely asking for trouble.

Mark