10 Replies Latest reply on Oct 13, 2006 10:00 AM by Stephen Schwenker

    exception=java.io.OptionalDataException when running the ser

    shimi carmeli Newbie

      Hello,

      I'm trying to run JBOSS server , after installing it . After getting a message that the server started I'm also getting this message:
      ERROR [UDP] exception=java.io.OptionalDataException
      at java.io.ObjectInputStream.readObject0(Unknown Source)
      at java.io.ObjectInputStream.readObject(Unknown Source)
      at org.jgroups.util.List.readExternal(List.java:304)
      at org.jgroups.protocols.UDP.handleIncomingUdpPacket

      Is someone fimiliar with that?

      This is the full output:

      JAVA_HOME is not set. Unexpected results may occur.
      Set JAVA_HOME to the directory of your local JDK to avoid this message.
      ===============================================================================
      .
      JBoss Bootstrap Environment
      .
      JBOSS_HOME: C:\Program Files\jboss-4.0.4.CR2\bin\\..
      .
      JAVA: java
      .
      JAVA_OPTS: -Dprogram.name=run.bat -Xms128m -Xmx512m
      .
      CLASSPATH: \lib\tools.jar;C:\Program Files\jboss-4.0.4.CR2\bin\\run.jar
      .
      ===============================================================================
      .
      15:36:17,734 INFO [Server] Starting JBoss (MX MicroKernel)...
      15:36:17,734 INFO [Server] Release ID: JBoss [Zion] 4.0.4.CR2 (build: CVSTag=JB
      oss_4_0_4_CR2 date=200603311500)
      15:36:17,734 INFO [Server] Home Dir: C:\Program Files\jboss-4.0.4.CR2
      15:36:17,734 INFO [Server] Home URL: file:/C:/Program Files/jboss-4.0.4.CR2/
      15:36:17,750 INFO [Server] Patch URL: null
      15:36:17,750 INFO [Server] Server Name: default
      15:36:17,750 INFO [Server] Server Home Dir: C:\Program Files\jboss-4.0.4.CR2\se
      rver\default
      15:36:17,750 INFO [Server] Server Home URL: file:/C:/Program Files/jboss-4.0.4.
      CR2/server/default/
      15:36:17,750 INFO [Server] Server Log Dir: C:\Program Files\jboss-4.0.4.CR2\ser
      ver\default\log
      15:36:17,750 INFO [Server] Server Temp Dir: C:\Program Files\jboss-4.0.4.CR2\se
      rver\default\tmp
      15:36:17,750 INFO [Server] Root Deployment Filename: jboss-service.xml
      15:36:18,093 INFO [ServerInfo] Java version: 1.5.0_04,Sun Microsystems Inc.
      15:36:18,093 INFO [ServerInfo] Java VM: Java HotSpot(TM) Client VM 1.5.0_04-b05
      ,Sun Microsystems Inc.
      15:36:18,093 INFO [ServerInfo] OS-System: Windows XP 5.1,x86
      15:36:18,640 INFO [Server] Core system initialized
      15:36:20,046 INFO [Log4jService$URLWatchTimerTask] Configuring from URL: resour
      ce:log4j.xml
      15:36:23,953 INFO [SnmpAgentService] SNMP agent going active
      15:36:24,093 INFO [AspectDeployer] Deployed AOP: file:/C:/Program Files/jboss-4
      .0.4.CR2/server/default/deploy/tc5-cluster.sar/tc5-cluster.aop
      15:36:24,296 INFO [TreeCache] setting cluster properties from xml to: UDP(down_
      thread=false;enable_bundling=true;ip_ttl=2;loopback=false;max_bundle_size=64000;
      max_bundle_timeout=30;mcast_addr=230.1.2.7;mcast_port=45577;mcast_recv_buf_size=
      25000000;mcast_send_buf_size=640000;ucast_recv_buf_size=20000000;ucast_send_buf_
      size=640000;up_thread=false;use_incoming_packet_handler=true;use_outgoing_packet
      _handler=true):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thre
      ad=false):MERGE2(down_thread=false;max_interval=100000;min_interval=20000;up_thr
      ead=false):FD(down_thread=false;max_tries=5;shun=true;timeout=2500;up_thread=fal
      se):VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK
      (discard_delivered_msgs=true;down_thread=false;gc_lag=50;max_xmit_size=60000;ret
      ransmit_timeout=100,200,300,600,1200,2400,4800;up_thread=false;use_mcast_xmit=fa
      lse):UNICAST(down_thread=false;timeout=300,600,1200,2400,3600;up_thread=false):p
      bcast.STABLE(desired_avg_gossip=50000;down_thread=false;max_bytes=2100000;stabil
      ity_delay=1000;up_thread=false):pbcast.GMS(down_thread=false;join_retry_timeout=
      2000;join_timeout=3000;print_local_addr=true;shun=true;up_thread=false):FC(down_
      thread=false;max_credits=10000000;min_threshold=0.20;up_thread=false):FRAG2(down
      _thread=false;frag_size=60000;up_thread=false):pbcast.STATE_TRANSFER(down_thread
      =false;up_thread=false)
      15:36:24,703 INFO [WebService] Using RMI server codebase: http://bsc123-02:8083
      /
      15:36:24,781 WARN [EJBTimerServiceImpl] Cannot obtain TransactionManager from J
      NDI, using TxManager.getInstance(): javax.naming.NameNotFoundException: Transact
      ionManager not bound
      15:36:26,625 INFO [MailService] Mail Service bound to java:/Mail
      15:36:27,078 INFO [TreeCache] interceptor chain is:
      class org.jboss.cache.interceptors.CallInterceptor
      class org.jboss.cache.interceptors.PessimisticLockInterceptor
      class org.jboss.cache.interceptors.UnlockInterceptor
      class org.jboss.cache.interceptors.ReplicationInterceptor
      15:36:27,078 INFO [TreeCache] cache mode is REPL_ASYNC
      15:36:27,171 INFO [NamingService] JNDI bootstrap JNP=/0.0.0.0:1099, RMI=/0.0.0.
      0:1098, backlog=50, no client SocketFactory, Server SocketFactory=class org.jbos
      s.net.sockets.DefaultSocketFactory
      15:36:27,234 INFO [SubscriptionManager] Bound event dispatcher to java:comp/env
      /EventDispatcher
      15:36:27,234 INFO [DefaultPartition] Initializing
      15:36:27,281 INFO [STDOUT]
      -------------------------------------------------------
      GMS: address is bsc123-02:4458 (additional data: 19 bytes)
      -------------------------------------------------------
      15:36:30,093 INFO [DefaultPartition] Number of cluster members: 2
      15:36:30,093 INFO [DefaultPartition] Other members: 1
      15:36:30,093 INFO [DefaultPartition] Fetching state (will wait for 30000 millis
      econds):
      15:36:30,093 INFO [DefaultPartition] New cluster view for partition DefaultPart
      ition: 9 ([175.70.101.128:1099, 175.70.101.136:1099] delta: 0)
      15:36:30,125 INFO [DefaultPartition] I am (175.70.101.136:1099) received member
      shipChanged event:
      15:36:30,125 INFO [DefaultPartition] Dead members: 0 ([])
      15:36:30,125 INFO [DefaultPartition] New Members : 0 ([])
      15:36:30,125 INFO [DefaultPartition] All Members : 2 ([175.70.101.128:1099, 175
      .70.101.136:1099])
      15:36:30,390 INFO [HANamingService] Started ha-jndi bootstrap jnpPort=1100, bac
      klog=50, bindAddress=/0.0.0.0
      15:36:30,406 INFO [DetachedHANamingService$AutomaticDiscovery] Listening on /0.
      0.0.0:1102, group=230.0.0.4, HA-JNDI address=175.70.101.136:1100
      15:36:30,453 INFO [STDOUT]
      -------------------------------------------------------
      GMS: address is bsc123-02:4461
      -------------------------------------------------------
      15:36:32,468 INFO [TreeCache] viewAccepted(): [bsc123-02:4461|0] [bsc123-02:446
      1]
      15:36:32,468 INFO [TreeCache] my local address is bsc123-02:4461
      15:36:32,468 INFO [TreeCache] state could not be retrieved (must be first membe
      r in group)
      15:36:32,468 INFO [TreeCache] new cache is null (may be first member in cluster
      )
      15:36:32,468 INFO [TreeCache] Cache is started!!
      15:36:33,046 INFO [Embedded] Catalina naming disabled
      15:36:33,109 INFO [ClusterRuleSetFactory] Unable to find a cluster rule set in
      the classpath. Will load the default rule set.
      15:36:33,109 INFO [ClusterRuleSetFactory] Unable to find a cluster rule set in
      the classpath. Will load the default rule set.
      15:36:33,421 INFO [Http11BaseProtocol] Initializing Coyote HTTP/1.1 on http-0.0
      .0.0-8080
      15:36:33,421 INFO [Catalina] Initialization processed in 312 ms
      15:36:33,421 INFO [StandardService] Starting service jboss.web
      15:36:33,421 INFO [StandardEngine] Starting Servlet Engine: Apache Tomcat/5.5.1
      6
      15:36:33,468 INFO [StandardHost] XML validation disabled
      15:36:33,484 INFO [Catalina] Server startup in 63 ms
      15:36:33,687 INFO [TomcatDeployer] deploy, ctxPath=/invoker, warUrl=.../deploy/
      http-invoker.sar/invoker.war/
      15:36:34,000 INFO [WebappLoader] Dual registration of jndi stream handler: fact
      ory already defined
      15:36:34,421 INFO [TomcatDeployer] deploy, ctxPath=/, warUrl=.../deploy/jbosswe
      b-tomcat55.sar/ROOT.war/
      15:36:34,578 INFO [TomcatDeployer] deploy, ctxPath=/jbossws, warUrl=.../tmp/dep
      loy/tmp6464jbossws14.sar-contents/jbossws-exp.war/
      15:36:34,750 INFO [TomcatDeployer] deploy, ctxPath=/jbossmq-httpil, warUrl=.../
      deploy/jms/jbossmq-httpil.sar/jbossmq-httpil.war/
      15:36:34,937 INFO [TomcatDeployer] deploy, ctxPath=/web-console, warUrl=.../dep
      loy/management/console-mgr.sar/web-console.war/
      15:36:35,875 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/jboss-ha-local-jdbc.rar
      15:36:35,937 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/jboss-ha-xa-jdbc.rar
      15:36:35,968 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/jboss-local-jdbc.rar
      15:36:36,000 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/jboss-xa-jdbc.rar
      15:36:36,078 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/jms/jms-ra.rar
      15:36:36,125 INFO [RARDeployment] Required license terms exist, view META-INF/r
      a.xml in .../deploy/mail-ra.rar
      15:36:36,796 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jb
      oss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS'
      15:36:37,078 INFO [A] Bound to JNDI name: queue/A
      15:36:37,078 INFO [B] Bound to JNDI name: queue/B
      15:36:37,093 INFO [C] Bound to JNDI name: queue/C
      15:36:37,093 INFO [D] Bound to JNDI name: queue/D
      15:36:37,093 INFO [ex] Bound to JNDI name: queue/ex
      15:36:37,109 INFO [testTopic] Bound to JNDI name: topic/testTopic
      15:36:37,109 INFO [securedTopic] Bound to JNDI name: topic/securedTopic
      15:36:37,109 INFO [testDurableTopic] Bound to JNDI name: topic/testDurableTopic

      15:36:37,125 INFO [testQueue] Bound to JNDI name: queue/testQueue
      15:36:37,171 INFO [UILServerILService] JBossMQ UIL service available at : /0.0.
      0.0:8093
      15:36:37,203 INFO [DLQ] Bound to JNDI name: queue/DLQ
      15:36:37,375 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jb
      oss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA'
      15:36:37,421 INFO [TomcatDeployer] deploy, ctxPath=/jmx-console, warUrl=.../dep
      loy/jmx-console.war/
      15:36:37,625 INFO [Http11BaseProtocol] Starting Coyote HTTP/1.1 on http-0.0.0.0
      -8080
      15:36:37,765 INFO [ChannelSocket] JK: ajp13 listening on /0.0.0.0:8009
      15:36:37,765 INFO [JkMain] Jk running ID=0 time=0/62 config=null
      15:36:37,781 INFO [Server] JBoss (MX MicroKernel) [4.0.4.CR2 (build: CVSTag=JBo
      ss_4_0_4_CR2 date=200603311500)] Started in 20s:31ms
      15:36:42,187 ERROR [UDP] exception=java.io.OptionalDataException
      at java.io.ObjectInputStream.readObject0(Unknown Source)
      at java.io.ObjectInputStream.readObject(Unknown Source)
      at org.jgroups.util.List.readExternal(List.java:304)
      at org.jgroups.protocols.UDP.handleIncomingUdpPacket(UDP.java:673)
      at org.jgroups.protocols.UDP$IncomingPacketHandler.run(UDP.java:1332)
      at java.lang.Thread.run(Unknown Source)

      15:36:54,859 ERROR [UDP] exception=java.io.OptionalDataException
      at java.io.ObjectInputStream.readObject0(Unknown Source)
      at java.io.ObjectInputStream.readObject(Unknown Source)
      at org.jgroups.util.List.readExternal(List.java:304)
      at org.jgroups.protocols.UDP.handleIncomingUdpPacket(UDP.java:673)
      at org.jgroups.protocols.UDP$IncomingPacketHandler.run(UDP.java:1332)
      at java.lang.Thread.run(Unknown Source)

      15:37:12,875 ERROR [UDP] exception=java.io.OptionalDataException
      at java.io.ObjectInputStream.readObject0(Unknown Source)
      at java.io.ObjectInputStream.readObject(Unknown Source)
      at org.jgroups.util.List.readExternal(List.java:304)
      at org.jgroups.protocols.UDP.handleIncomingUdpPacket(UDP.java:673)
      at org.jgroups.protocols.UDP$IncomingPacketHandler.run(UDP.java:1332)
      at java.lang.Thread.run(Unknown Source)

      15:37:29,437 ERROR [UDP] exception=java.io.OptionalDataException
      at java.io.ObjectInputStream.readObject0(Unknown Source)
      at java.io.ObjectInputStream.readObject(Unknown Source)
      at org.jgroups.util.List.readExternal(List.java:304)
      at org.jgroups.protocols.UDP.handleIncomingUdpPacket(UDP.java:673)
      at org.jgroups.protocols.UDP$IncomingPacketHandler.run(UDP.java:1332)
      at java.lang.Thread.run(Unknown Source)



      Thanks,
      Shimi

        • 1. Re: exception=java.io.OptionalDataException when running the
          Vincent Yu Newbie

          I have exactly the same problem with Jboss 4.0.4.CR2.

          The exception ERROR [UDP] exception=java.io.OptionalDataException keeps ocurring about every 15 seconds.

          Any body can help? Or just how to prevent it from displaying? I think that JBoss is working fine.

          • 2. Re: exception=java.io.OptionalDataException when running the
            Shamsul Amry Newbie

            A quick solution to this is to modify the current log4j.xml in the server conf directory. Just add the following entry into it and all should be fine:

            <category name="org.jgroups.protocols.UDP">
             <priority value="FATAL"/>
             </category>


            • 3. Re: exception=java.io.OptionalDataException when running the
              Petr Zeman Newbie

              This helped me too. But I think it's workarround only, not solution, isn't it? ;o)
              Petr

              • 4. Re: exception=java.io.OptionalDataException when running the
                Stanislav Makarchuk Newbie

                JBoss 4.0.4.GA - same behaviour
                May be bug ?

                • 5. Re: exception=java.io.OptionalDataException when running the
                  claudefr Newbie

                  Same here, JBoss 4.0.4.GA, Windows XP

                  • 6. Re: exception=java.io.OptionalDataException when running the
                    Brian Newbie

                    I've got the exact same problem too. JBoss 4.0.4.GA, Windows XP. Any solution to this guys????

                    • 7. Re: exception=java.io.OptionalDataException when running the
                      Andy W. Clements Newbie

                      Hello Forum Folks,

                      I too, have been recieving this error. Seeing has there is no current solution I decided to investigate into the code. JBoss-4.0.4GA is using JGroups-2.2.7. I was able to get the source from here:

                      http://www.codezoo.com/pub/component/174?category=7

                      Looking at the handleIncomingUdpPacket method in the org.jgroups.protocols.UDP class we get this:

                      /**
                       * Processes a packet read from either the multicast or unicast socket. Needs to be synchronized because
                       * mcast or unicast socket reads can be concurrent
                       */
                       void handleIncomingUdpPacket(byte[] data) {
                       ByteArrayInputStream inp_stream;
                       ObjectInputStream inp;
                       Message msg=null;
                       List l; // used if bundling is enabled
                      
                       try {
                       // skip the first n bytes (default: 4), this is the version info
                       inp_stream=new ByteArrayInputStream(data, VERSION_LENGTH, data.length - VERSION_LENGTH);
                       inp=new ObjectInputStream(inp_stream);
                       if(enable_bundling) {
                       l=new List();
                       l.readExternal(inp);
                       for(Enumeration en=l.elements(); en.hasMoreElements();) {
                       msg=(Message)en.nextElement();
                       try {
                       handleMessage(msg);
                       }
                       catch(Throwable t) {
                       if(log.isErrorEnabled()) log.error("failure: " + t.toString());
                       }
                       }
                       }
                       else {
                       msg=new Message();
                       msg.readExternal(inp);
                       handleMessage(msg);
                       }
                       }
                       catch(Throwable e) {
                       if(log.isErrorEnabled()) log.error("exception=" + Util.getStackTrace(e));
                       }
                       }
                      



                      First, we must thank Bela for making such clean, readable code.

                      Second, What is happening here is the server is receiving a UDP packet from the multicast from somewhere in your network. If we look at the code for the OptionalDataException we get the following description of what is happening:

                      Exception indicating the failure of an object read operation due to
                      unread primitive data, or the end of data belonging to a serialized
                      object in the stream.
                      An attempt was made to read an object when the next element in the
                      stream is primitive data. In this case, the OptionalDataException's
                      length field is set to the number of bytes of primitive data
                      immediately readable from the stream, and the eof field is set to
                      false.


                      So, I believe what is happening is the following: somebody is sending mutlicast UDP packets to your machine and jboss clustering is picking them up and trying to create objects out of them. Since they are not objects, it throws an error.

                      So, unless your clustering is not working correctly, it hopefully can be assumed that this error can be ignored. The best way to do that is to modfiy your log4j.xml as amry stated before.

                      It should be noted that if you change the enabled_bundling in the server/all/deploy/tc5-cluster.sar/META-INF/jboss-service.xml to false, you will recieve a different error:
                      16:00:54,286 ERROR [UDP] exception=java.io.EOFException
                       at java.io.DataInputStream.readInt(DataInputStream.java:358)
                       at java.io.ObjectInputStream$BlockDataInputStream.readInt(ObjectInputStream.java:2724)
                       at java.io.ObjectInputStream.readInt(ObjectInputStream.java:919)
                       at org.jgroups.Message.readExternal(Message.java:479)
                       at org.jgroups.protocols.UDP.handleIncomingUdpPacket(UDP.java:686)
                       at org.jgroups.protocols.UDP$IncomingPacketHandler.run(UDP.java:1332)
                       at java.lang.Thread.run(Thread.java:595)
                      


                      which, from looking at the code from both jgroups and java.io, confirms the above.


                      --Andy

                      • 9. Re: exception=java.io.OptionalDataException when running the
                        Rohit Chowdhary Newbie

                        You can completely avoid this problem by changing the port number for the UDP multicast in the cluster-service.xml and tc5-cluster.sar/META-INF/jboss-service.xml (the latter is important).

                        This would be better as your server or servers (change them all if you have a cluster) would be listening on a different port and you would save some CPU cycles by not processing the messages from other servers that are not part of your cluster.

                        This would be a better solution than supressing the errors from the server logs.

                        • 10. Re: exception=java.io.OptionalDataException when running the
                          Stephen Schwenker Newbie

                          I'm getting this same error even though I'm running two different clusters on different multicast addresses.

                          Should this still be happening?

                          Thank you,


                          Steve.