exception=java.io.OptionalDataException when running the ser

[bsc123]

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

[crazybuddy]

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.

[amry]

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>

[ipetros]

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

[spice1978]

JBoss 4.0.4.GA - same behaviour
May be bug ?

[claudiobosticco]

Same here, JBoss 4.0.4.GA, Windows XP

[binario]

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

[awclemen]

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

[jacxia81]

great reply, thanks

[rcjboss]

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.

[saschwen]

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.