1 2 Previous Next 15 Replies Latest reply on Oct 11, 2006 4:16 AM by manik

    [TreeCacheMarshaller140] Unknown Magic Number 49

    bpapez

      Since switching to JBossCache 1.4.0.GA I get many of the following log-entries:

      12:08:59,360 ERROR [TreeCacheMarshaller140] Unknown Magic Number 49
      12:08:59,379 INFO [VersionAwareMarshaller] Caught exception unmarshalling stream with specific versioned marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140. Attempting to try again with legacy marshaller class org.jboss.cache.marshall.LegacyTreeCacheMarshaller
      12:08:59,390 ERROR [RpcDispatcher] exception=java.io.StreamCorruptedException: invalid stream header
      12:09:13,947 ERROR [TreeCacheMarshaller140] Unknown Magic Number 49
      12:09:13,962 INFO [VersionAwareMarshaller] Caught exception unmarshalling stream with specific versioned marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140. Attempting to try again with legacy marshaller class org.jboss.cache.marshall.LegacyTreeCacheMarshaller
      12:09:13,970 ERROR [RpcDispatcher] exception=java.io.StreamCorruptedException: invalid stream header

      What does that mean or what can we do about it?

        • 1. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
          manik

          Hi,

          This has to do with the new marshaller in 1.4.0 not recognising an object that has been serialised as a part of an RPC call and not being able to unmarshal it.

          Could you post some more logs - say the last 20 lines or so before this happened? Also, could you describe what was going on at the time, if you can accurately recreate it?

          Cheers,
          Manik

          • 2. Re: [TreeCacheMarshaller140] Unknown Magic Number 49

            Hello!

            I started to see this in our logs to. We are using 1.4.0SP1 and JGroups 2.2.9.3.

            Isolated the error and it seems like when you put a String with a length larger than 32767 this error occurs. The number in the error message is the byte of the the first char in the string. I get Unknown Magic Number 97 when using a string that has a 'a' as the first char and 60 when it's a '<'.

            I wrote a testcase on this and i can recreate the error everytime. The testcase is only using jars from the 1.4.0SP1 dist-lib (wich includes JGroups 2.2.9.2) and a unmodified (besides mcast_addr and mcast_port) replAsync-service.xml from the dist.

            The testcase sets up two instances and first tries to put a string with the length of 32768 wich fails. Then it tries to put a string with the length of 32767 wich works OK.

            32768 / 4 = the FRAG frag_size in the config. Tried to double this value but no luck....

            Is this a bug or a limit in the replication?





            29626 [main] INFO com.hm.caab.treecachestandalone.TestTreeCache - Length of string is 32768
            29626 [main] DEBUG org.jboss.cache.interceptors.TxInterceptor - (10.60.15.101:4389) call on method [_put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true)]
            29907 [main] DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method _put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true)
            30157 [main] DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT for owner Thread[main,5,main]
            30157 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects
            30157 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects, caller=Thread[main,5,main], lock=
            30172 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30172 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com
            30172 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com, caller=Thread[main,5,main], lock=
            30172 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30172 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com/hm
            30172 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm, caller=Thread[main,5,main], lock=
            30172 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30172 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com/hm/caab
            30172 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab, caller=Thread[main,5,main], lock=
            30172 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30172 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com/hm/caab/treecachestandalone
            30172 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab/treecachestandalone, caller=Thread[main,5,main], lock=
            30172 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab/treecachestandalone, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30188 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache
            30188 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache, caller=Thread[main,5,main], lock=
            30188 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            30188 [main] DEBUG org.jboss.cache.Node - created child: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT
            30188 [main] DEBUG org.jboss.cache.Node - acquiring WL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, caller=Thread[main,5,main], lock=
            30188 [main] DEBUG org.jboss.cache.Node - acquired WL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, caller=Thread[main,5,main], lock=write owner=Thread[main,5,main]
            30188 [main] DEBUG org.jboss.cache.interceptors.CallInterceptor - Invoking method _put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true) on cache.
            30454 [main] DEBUG org.jboss.cache.TreeCache - _put(null, "/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT", ES_ES_HTML, aa[removed long aaaa-string in log here...])
            30719 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], write owner=Thread[main,5,main]]}
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT: write owner=Thread[main,5,main]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone/TestTreeCache: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects: read owners=[Thread[main,5,main]]
            30735 [main] DEBUG org.jboss.cache.interceptors.ReplicationInterceptor - Non-tx crud meth
            30735 [main] DEBUG org.jboss.cache.interceptors.ReplicationInterceptor - invoking method _put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true), members=[10.60.15.101:4389, 10.60.15.101:4393], mode=REPL_ASYNC, exclude_self=true, timeout=20000
            31032 [main] DEBUG org.jboss.cache.interceptors.ReplicationInterceptor - Broadcasting call _put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true) to recipient list null
            31297 [main] DEBUG org.jboss.cache.TreeCache - callRemoteMethods(): valid members are [10.60.15.101:4393] method: _replicate(_put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true))
            31579 [main] DEBUG org.jgroups.blocks.RpcDispatcher - dests=[10.60.15.101:4393], method_call=_replicate(_put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true)), mode=6, timeout=20000
            31860 [main] DEBUG org.jboss.cache.marshall.TreeCacheMarshaller140 - Marshalling object _replicate(_put(null, /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, aa[removed long aaaa-string in log here...], true))
            32157 [main] DEBUG org.jgroups.blocks.RpcDispatcher - real_dests=[10.60.15.101:4393]
            32172 [main] DEBUG org.jgroups.blocks.GroupRequest - sending request (id=1156927873256)
            32172 [DownHandler (GMS)] DEBUG org.jgroups.protocols.FRAG - message size is 32990, will fragment (frag_size=16384)
            32172 [main] DEBUG org.jgroups.blocks.GroupRequest - received all responses: [GroupRequest:
            req_id=1156927873256
            caller=10.60.15.101:4389
            10.60.15.101:4393: sender=10.60.15.101:4393, retval=null, received=false, suspected=false

            request_msg: [dst: , src: (1 headers), size = 32913 bytes]
            rsp_mode: GET_NONE
            done: false
            timeout: 20000
            expected_mbrs: 0
            ]
            32172 [DownHandler (GMS)] DEBUG org.jgroups.protocols.FRAG - fragmenting packet to <all members> (size=65836) into 3 fragment(s) [frag_size=16384]
            32172 [main] DEBUG org.jgroups.blocks.RpcDispatcher - responses: [sender=10.60.15.101:4393, retval=null, received=false, suspected=false]

            32172 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.NAKACK - sending msg #3
            32172 [main] DEBUG org.jboss.cache.interceptors.ReplicationInterceptor - responses=[]
            32188 [main] DEBUG org.jboss.cache.interceptors.TxInterceptor - (10.60.15.101:4389) call on method [_get(/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, true)]
            32188 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.NAKACK - sending msg #4
            32188 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.NAKACK - sending msg #5
            32188 [main] DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method _get(/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, true)
            32188 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP - sending msg to null (src=10.60.15.101:4389), headers are {NAKACK=[MSG, seqno=3], FRAG=[id=1, frag_id=0, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32188 [main] DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT for owner Thread[main,5,main]
            32188 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)16485 bytes from 10.60.15.101:4390
            32188 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)16485 bytes from 10.60.15.101:4390
            32188 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP - sending msg to null (src=10.60.15.101:4389), headers are {NAKACK=[MSG, seqno=4], FRAG=[id=1, frag_id=1, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32188 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 16384 bytes], headers are {NAKACK=[MSG, seqno=3], FRAG=[id=1, frag_id=0, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32188 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 16384 bytes], headers are {NAKACK=[MSG, seqno=3], FRAG=[id=1, frag_id=0, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32188 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects, caller=Thread[main,5,main], lock=
            32204 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4389] received 10.60.15.101:4389#3
            32204 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4393] received 10.60.15.101:4389#3
            32204 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)16485 bytes from 10.60.15.101:4390
            32204 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)16485 bytes from 10.60.15.101:4390
            32204 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32204 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 16384 bytes], headers are {NAKACK=[MSG, seqno=4], FRAG=[id=1, frag_id=1, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32204 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP - sending msg to null (src=10.60.15.101:4389), headers are {NAKACK=[MSG, seqno=5], FRAG=[id=1, frag_id=2, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32204 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 16384 bytes], headers are {NAKACK=[MSG, seqno=4], FRAG=[id=1, frag_id=1, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32219 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com, caller=Thread[main,5,main], lock=
            32219 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4393] received 10.60.15.101:4389#4
            32219 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4389] received 10.60.15.101:4389#4
            32219 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)323 bytes from 10.60.15.101:4390
            32219 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - received (mcast)323 bytes from 10.60.15.101:4390
            32219 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32219 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 222 bytes], headers are {NAKACK=[MSG, seqno=5], FRAG=[id=1, frag_id=2, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32219 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP - message is [dst: 228.8.8.9:45570, src: 10.60.15.101:4389 (3 headers), size = 222 bytes], headers are {NAKACK=[MSG, seqno=5], FRAG=[id=1, frag_id=2, num_frags=3], UDP=[channel_name=TreeCache-Cluster]}
            32235 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4393] received 10.60.15.101:4389#5
            32235 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.pbcast.NAKACK - 10.60.15.101:4389] received 10.60.15.101:4389#5
            32235 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm, caller=Thread[main,5,main], lock=
            32235 [UpHandler (UNICAST)] DEBUG org.jgroups.protocols.FRAG - assembled_msg is [dst: , src: (1 headers), size = 32913 bytes]
            32235 [UpHandler (UNICAST)] DEBUG org.jgroups.protocols.FRAG - assembled_msg is [dst: , src: (1 headers), size = 32913 bytes]
            32235 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32235 [UpHandler (STATE_TRANSFER)] DEBUG org.jgroups.blocks.RequestCorrelator - discarded request from 10.60.15.101:4389 as we are not part of destination list (local_addr=10.60.15.101:4389, hdr=[Header: name=MessageDispatcher, type=REQ, id=1156927873256, rsp_expected=false], dest_mbrs=[10.60.15.101:4393])
            32235 [UpHandler (STATE_TRANSFER)] DEBUG org.jgroups.blocks.RequestCorrelator - calling (org.jgroups.blocks.RpcDispatcher) with request 1156927873256
            32266 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab, caller=Thread[main,5,main], lock=
            32266 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32266 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab/treecachestandalone, caller=Thread[main,5,main], lock=
            32266 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab/treecachestandalone, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32266 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache, caller=Thread[main,5,main], lock=
            32266 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=7 isLong=false
            32266 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32266 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=3 isLong=false
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32282 [main] DEBUG org.jboss.cache.Node - acquiring RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, caller=Thread[main,5,main], lock=
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=2 isLong=false
            32282 [main] DEBUG org.jboss.cache.Node - acquired RL: fqn=/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, caller=Thread[main,5,main], lock=read owners=[Thread[main,5,main]]
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=4 isLong=false
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=19 isLong=false
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=13 isLong=false
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32282 [main] DEBUG org.jboss.cache.interceptors.CallInterceptor - Invoking method _get(/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT, ES_ES_HTML, true) on cache.
            32282 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=9 isLong=false
            32297 [main] DEBUG org.jboss.cache.TreeCache - _get("/objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT", ES_ES_HTML, "true")
            32297 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[main,5,main]=[read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]], read owners=[Thread[main,5,main]]]}
            32297 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32297 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone/TestTreeCache/XMLOUTPUT: read owners=[Thread[main,5,main]]
            32297 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=10 isLong=false
            32297 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - readString::pulling data to Buffer at pos 0 size= 0
            32297 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone/TestTreeCache: read owners=[Thread[main,5,main]]
            32297 [UpHandler (STATE_TRANSFER)] DEBUG org.jboss.serial.util.StringUtil - Reading string with utfSize=-32768 isLong=false
            32297 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab/treecachestandalone: read owners=[Thread[main,5,main]]
            10:51:13,397 ERROR [TreeCacheMarshaller140] Unknown Magic Number 97
            32313 [UpHandler (STATE_TRANSFER)] ERROR org.jboss.cache.marshall.TreeCacheMarshaller140 - Unknown Magic Number 97
            32313 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm/caab: read owners=[Thread[main,5,main]]
            10:51:13,397 INFO [VersionAwareMarshaller] Caught exception unmarshalling stream with specific versioned marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140. Attempting to try again with legacy marshaller class org.jboss.cache.marshall.LegacyTreeCacheMarshaller
            32313 [UpHandler (STATE_TRANSFER)] INFO org.jboss.cache.marshall.VersionAwareMarshaller - Caught exception unmarshalling stream with specific versioned marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140. Attempting to try again with legacy marshaller class org.jboss.cache.marshall.LegacyTreeCacheMarshaller
            32313 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com/hm: read owners=[Thread[main,5,main]]
            10:51:13,397 ERROR [RpcDispatcher] exception=java.io.StreamCorruptedException: invalid stream header
            32313 [UpHandler (STATE_TRANSFER)] ERROR org.jgroups.blocks.RpcDispatcher - exception=java.io.StreamCorruptedException: invalid stream header
            32313 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects/com: read owners=[Thread[main,5,main]]
            32329 [main] DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /objects: read owners=[Thread[main,5,main]]
            32329 [main] DEBUG org.jboss.cache.interceptors.ReplicationInterceptor - Non-tx and non crud meth

            • 3. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
              belaban

              I fixed a problem with FRAG in 2.3 (http://jira.jboss.com/jira/browse/JGRP-215), can you either upgrade to 2.3 or use FRAG2 instead of FRAG, to see whether this is a JGroups problem ? If the problem disappears with 2.3, then it was a JGroups problem, otherwise it might be a problem with the JBossCache Marshaller.

              • 4. Re: [TreeCacheMarshaller140] Unknown Magic Number 49

                Tried with JGroups 2.3SP1 and FRAG2 (also with 2.3SP1) but no luck....

                11:54:43,182 INFO [TestTreeCache] ------------------ Running testPutToBigString -------------------------
                11:54:47,026 INFO [TestTreeCache] Length of string is 32768
                11:54:47,073 INFO [TestTreeCache] Sleeping for 2000 millis...
                11:54:47,104 ERROR [TreeCacheMarshaller140] Unknown Magic Number 97
                11:54:47,104 INFO [VersionAwareMarshaller] Caught exception unmarshalling stream with specific versioned marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140. Attempting to try again with legacy marshaller class org.jboss.cache.marshall.LegacyTreeCacheMarshaller
                11:54:47,104 ERROR [RpcDispatcher] exception marshalling object
                java.io.StreamCorruptedException: invalid stream header
                at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:753)
                at java.io.ObjectInputStream.(ObjectInputStream.java:268)
                at org.jboss.invocation.MarshalledValueInputStream.(MarshalledValueInputStream.java:60)
                at org.jboss.cache.marshall.VersionAwareMarshaller.objectFromByteBuffer(VersionAwareMarshaller.java:184)
                at org.jgroups.blocks.RpcDispatcher.handle(RpcDispatcher.java:215)
                at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:597)
                at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:497)
                at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:320)
                at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:722)
                at org.jgroups.JChannel.up(JChannel.java:1034)
                at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:377)
                at org.jgroups.stack.ProtocolStack.receiveUpEvent(ProtocolStack.java:393)
                at org.jgroups.stack.Protocol.passUp(Protocol.java:538)
                at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:149)
                at org.jgroups.stack.UpHandler.run(Protocol.java:60)

                • 5. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                  manik

                  Ok, let me take a look at this.

                  Have you been able to boil this down to a simple unit test?

                  • 6. Re: [TreeCacheMarshaller140] Unknown Magic Number 49

                    Jupp. Here:

                    package com.hm.caab.treecachestandalone;
                    
                    import junit.framework.Test;
                    import junit.framework.TestCase;
                    import junit.framework.TestSuite;
                    import org.apache.log4j.BasicConfigurator;
                    import org.apache.log4j.Logger;
                    import org.jboss.cache.Fqn;
                    import org.jboss.cache.PropertyConfigurator;
                    import org.jboss.cache.TreeCache;
                    
                    /**
                     * Tests put with a large string
                     * <p/>
                     * Date: 2006-aug-29
                     *
                     * @author Carl Abramsson / H&M
                     */
                    public class TestTreeCache extends TestCase {
                    
                     protected static Logger log = Logger.getLogger(TestTreeCache.class.getName());
                    
                     static {
                     //String resource = "/log4j.xml";
                     //URL configFileResource = TestTreeCache.class.getResource(resource);
                     //DOMConfigurator.configure(configFileResource.getFile());
                     BasicConfigurator.configure();
                     }
                    
                     TreeCache treeCache1 = null;
                     TreeCache treeCache2 = null;
                    
                     private static final String CONFIG_FILE = "replAsync-service.xml";
                    
                     protected void setUp() throws Exception {
                     super.setUp();
                     log.info("------------------ set up start -------------------------");
                    
                     // Cache 1
                     treeCache1 = new TreeCache();
                     PropertyConfigurator config1 = new PropertyConfigurator();
                     config1.configure(treeCache1, CONFIG_FILE); // Load config file from classpath
                     treeCache1.startService();
                     sleepThread((long) 10000);
                    
                     // Cache 2
                     treeCache2 = new TreeCache();
                    
                     PropertyConfigurator config2 = new PropertyConfigurator();
                     config2.configure(treeCache2, CONFIG_FILE); // Load config file from classpath
                     treeCache2.startService();
                    
                     sleepThread((long) 10000);
                     log.info("------------------ set up finished -------------------------");
                     }
                    
                     protected void tearDown() throws Exception {
                     log.info("------------------ tear down start -------------------------");
                     sleepThread((long) 1000);
                     super.tearDown();
                    
                     if (treeCache1 != null) {
                     log.info(treeCache1);
                     treeCache1.stopService();
                     treeCache1.destroyService();
                     treeCache1 = null;
                     }
                     if (treeCache2 != null) {
                     log.info(treeCache2);
                     treeCache2.stopService();
                     treeCache2.destroyService();
                     treeCache2 = null;
                     }
                     sleepThread((long) 10);
                     log.info("------------------ tear down finito -------------------------");
                    
                     }
                    
                     public void testPutToBigString() throws Exception {
                     log.info("------------------ Running testPutToBigString -------------------------");
                    
                     String region = "XMLOUTPUT";
                     String currentKey = "ES_ES_HTML";
                     Object fromCache;
                    
                     Fqn fqn = createFqn(TestTreeCache.class, region);
                     String aString = createString(32768);
                     log.info("Length of string is " + aString.length());
                    
                     treeCache1.put(fqn, currentKey, aString);
                     // Check cache1
                     fromCache = treeCache1.get(fqn, currentKey);
                     assertNotNull(fromCache);
                     assertEquals(fromCache, aString);
                    
                     sleepThread(2000);
                    
                     // Check cache2
                     fromCache = treeCache2.get(fqn, currentKey);
                     assertNotNull(fromCache);
                     assertEquals(fromCache, aString);
                    
                    
                     log.info("------------------ finished testPutToBigString -------------------------");
                     }
                    
                     public void testPutString() throws Exception {
                     log.info("------------------ Running testPutString -------------------------");
                    
                     String region = "XMLOUTPUT";
                     String currentKey = "ES_ES_HTML";
                     Object fromCache;
                    
                     Fqn fqn = createFqn(TestTreeCache.class, region);
                     String aString = createString(32767);
                    
                     treeCache1.put(fqn, currentKey, aString);
                     // Check cache1
                     fromCache = treeCache1.get(fqn, currentKey);
                     assertNotNull(fromCache);
                     assertEquals(fromCache, aString);
                    
                     sleepThread(2000);
                    
                     // Check cache2
                     fromCache = treeCache2.get(fqn, currentKey);
                     assertNotNull(fromCache);
                     assertEquals(fromCache, aString);
                    
                    
                     log.info("------------------ finished testPutString -------------------------");
                     }
                    
                     private String createString(int length) {
                     String theString = "";
                     while (theString.length() < length) {
                     theString = theString + "a";
                     }
                     return theString;
                     }
                    
                    
                     protected Fqn createFqn(Class c, String region) {
                     return Fqn.fromString("/objects" + Fqn.SEPARATOR + c.getName().replaceAll("\\.", "/") + Fqn.SEPARATOR + region);
                     }
                    
                     /**
                     * Puts the current thread to sleep for the desired number of ms, suppressing
                     * any exceptions.
                     *
                     * @param sleeptime number of ms to sleep
                     */
                     protected static void sleepThread(long sleeptime) {
                     log.info("Sleeping for " + sleeptime + " millis...");
                     try {
                     Thread.sleep(sleeptime);
                     }
                     catch (InterruptedException ie) {
                     }
                     log.info("Exiting sleep....");
                     }
                    
                     public static Test suite() {
                     return new TestSuite(TestTreeCache.class);
                     }
                    }
                    
                    
                    


                    And the config:



                    <?xml version="1.0" encoding="UTF-8"?>
                    
                    <!-- ===================================================================== -->
                    <!-- -->
                    <!-- Sample TreeCache Service Configuration -->
                    <!-- -->
                    <!-- ===================================================================== -->
                    
                    <server>
                    
                     <classpath codebase="./lib" archives="jboss-cache.jar, jgroups.jar"/>
                    
                    
                     <!-- ==================================================================== -->
                     <!-- Defines TreeCache configuration -->
                     <!-- ==================================================================== -->
                    
                     <mbean code="org.jboss.cache.TreeCache"
                     name="jboss.cache:service=TreeCache">
                    
                     <depends>jboss:service=Naming</depends>
                     <depends>jboss:service=TransactionManager</depends>
                    
                     <!--
                     Configure the TransactionManager
                     -->
                     <attribute name="TransactionManagerLookupClass">org.jboss.cache.DummyTransactionManagerLookup</attribute>
                    
                     <!--
                     Isolation level : SERIALIZABLE
                     REPEATABLE_READ (default)
                     READ_COMMITTED
                     READ_UNCOMMITTED
                     NONE
                     -->
                     <attribute name="IsolationLevel">REPEATABLE_READ</attribute>
                    
                     <!--
                     Valid modes are LOCAL
                     REPL_ASYNC
                     REPL_SYNC
                     INVALIDATION_ASYNC
                     INVALIDATION_SYNC
                     -->
                     <attribute name="CacheMode">REPL_ASYNC</attribute>
                    
                     <!--
                     Just used for async repl: use a replication queue
                     -->
                     <attribute name="UseReplQueue">false</attribute>
                    
                     <!--
                     Replication interval for replication queue (in ms)
                     -->
                     <attribute name="ReplQueueInterval">0</attribute>
                    
                     <!--
                     Max number of elements which trigger replication
                     -->
                     <attribute name="ReplQueueMaxElements">0</attribute>
                    
                     <!-- Name of cluster. Needs to be the same for all clusters, in order
                     to find each other
                     -->
                     <attribute name="ClusterName">TreeCache-Cluster</attribute>
                    
                     <!-- JGroups protocol stack properties. Can also be a URL,
                     e.g. file:/home/bela/default.xml
                     <attribute name="ClusterProperties"></attribute>
                     -->
                    
                     <attribute name="ClusterConfig">
                     <config>
                     <!-- UDP: if you have a multihomed machine,
                     set the bind_addr attribute to the appropriate NIC IP address -->
                     <!-- UDP: On Windows machines, because of the media sense feature
                     being broken with multicast (even after disabling media sense)
                     set the loopback attribute to true -->
                     <UDP mcast_addr="228.8.8.9" mcast_port="45570"
                     ip_ttl="64" ip_mcast="true"
                     mcast_send_buf_size="150000" mcast_recv_buf_size="80000"
                     ucast_send_buf_size="150000" ucast_recv_buf_size="80000"
                     loopback="false"/>
                     <PING timeout="2000" num_initial_members="3"
                     up_thread="false" down_thread="false"/>
                     <MERGE2 min_interval="10000" max_interval="20000"/>
                     <!-- <FD shun="true" up_thread="true" down_thread="true" />-->
                     <FD_SOCK/>
                     <VERIFY_SUSPECT timeout="1500"
                     up_thread="false" down_thread="false"/>
                     <pbcast.NAKACK gc_lag="50" retransmit_timeout="600,1200,2400,4800"
                     max_xmit_size="8192" up_thread="false" down_thread="false"/>
                     <UNICAST timeout="600,1200,2400" window_size="100" min_threshold="10"
                     down_thread="false"/>
                     <pbcast.STABLE desired_avg_gossip="20000"
                     up_thread="false" down_thread="false"/>
                     <FRAG frag_size="8192"
                     down_thread="false" up_thread="false"/>
                     <pbcast.GMS join_timeout="5000" join_retry_timeout="2000"
                     shun="true" print_local_addr="true"/>
                     <pbcast.STATE_TRANSFER up_thread="true" down_thread="true"/>
                     </config>
                     </attribute>
                    
                     <!--
                     Whether or not to fetch state on joining a cluster
                     NOTE this used to be called FetchStateOnStartup and has been renamed to be more descriptive.
                     -->
                     <attribute name="FetchInMemoryState">true</attribute>
                    
                     <!--
                     The max amount of time (in milliseconds) we wait until the
                     initial state (ie. the contents of the cache) are retrieved from
                     existing members in a clustered environment
                     -->
                     <attribute name="InitialStateRetrievalTimeout">20000</attribute>
                    
                     <!--
                     Number of milliseconds to wait until all responses for a
                     synchronous call have been received.
                     -->
                     <attribute name="SyncReplTimeout">20000</attribute>
                    
                     <!-- Max number of milliseconds to wait for a lock acquisition -->
                     <attribute name="LockAcquisitionTimeout">15000</attribute>
                    
                    
                     <!-- Name of the eviction policy class. -->
                     <attribute name="EvictionPolicyClass"></attribute>
                    
                     <!--
                     Indicate whether to use region based marshalling or not. Set this to true if you are running under a scoped
                     class loader, e.g., inside an application server. Default is "false".
                     -->
                     <attribute name="UseRegionBasedMarshalling">false</attribute>
                    
                     </mbean>
                    
                    
                     <!-- Uncomment to get a graphical view of the TreeCache MBean above -->
                     <!-- <mbean code="org.jboss.cache.TreeCacheView" name="jboss.cache:service=TreeCacheView">-->
                     <!-- <depends>jboss.cache:service=TreeCache</depends>-->
                     <!-- <attribute name="CacheService">jboss.cache:service=TreeCache</attribute>-->
                     <!-- </mbean>-->
                    
                    
                    </server>
                    
                    


                    • 7. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                      manik

                      Thanks.

                      Ok, I see it - I've added a similar test to my test suite now.

                      See http://jira.jboss.com/jira/browse/JBCACHE-756

                      Cheers,
                      Manik

                      • 8. Re: [TreeCacheMarshaller140] Unknown Magic Number 49

                        Cool.

                        Yeeah, did just see that there´s a 1.4.0SP2 planned now with "my" two bugs. Thanks! :-D

                        • 9. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                          belaban

                          Manik, please let me know if this turns out to be a JGroups problem, so I could look at it.
                          Cheers.

                          • 10. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                            manik

                            Bela, looks like a JBC problem.

                            Strings are written to the stream using the marshaller using ObjectOutputStream.writeUTF() - which has this limitation:

                            http://java.sun.com/j2se/1.5.0/docs/api/java/io/DataOutput.html#writeUTF(java.lang.String)

                            According to the documentation, this limits string lengths to 65535 bytes.

                            Carl, are you using multi-byte Strings (accents, etc)? 32767 characters x 2 bytes per char = 65534 bytes. 32768 characters (at 2 bytes per char) will cross this limit and you will see an overflow.

                            The fix to this problem would be NOT to use writeUTF() but to serialize the Strings themselves onto the stream, but this is less efficient.

                            • 11. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                              belaban

                              OK, ic

                              • 12. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                                manik

                                This may just be a problem with jboss-serialization.jar and nothing to do with JBoss Cache at all. Clebert's investigating the potential problem with jboss-serialization.

                                http://jira.jboss.com/jira/browse/JBSER-89

                                FYI, JBoss Cache 1.4.0.GA and 1.4.0.SP1 both ship with jboss-serialization-1.0.1.GA. The potential upside is that if it is a bug in jboss-serialization, fixing the issue will just be upgrading the one jar, and it should be backward-compatible with JBoss Cache 1.4.0.XX.

                                • 13. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                                  clebert.suconic

                                   


                                  The fix to this problem would be NOT to use writeUTF() but to serialize the Strings themselves onto the stream, but this is less efficient.


                                  I don't think this would change the performance at al.

                                  Strings are specially treated on Java Serialization. The routine for serializing strings is basically the same as writeUTF, but considering also long buffers.

                                  I just had to support the same thing on JBoss Serialization.

                                  I had a bug which I'm fixing right now. I'm writing a short, and reading back the same short but instead of using readUnsignedShort I was using readShort what would truncate the size of any string between 0xefff and 0xffff bytes (because of the sign bit)


                                  Clebert

                                  • 14. Re: [TreeCacheMarshaller140] Unknown Magic Number 49
                                    manik

                                    yes, basically once we pinpointed that this was because of JBSER-89, my comments re: writeUTF is irrelevant.

                                    1 2 Previous Next