Re: getAllClusterSessions gives OptionalDataException
Op vrijdag, 8 juli 2011 21:55 schreef Christopher Schultz ch...@christopherschultz.net: -BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Ronald, On 7/8/2011 5:33 AM, Ronald Klop wrote: After some fun with debugging Tomcat on my live server (because I couldn't reproduce it in test) it looks like a concurrency bug in my own code. D'oh. I think I modify a HashMap which is serialized in the session. For some reason I don't get a ConcurrentModificationException, but in the byte[] in DeltaManager.handleALL_SESSION_DATA I had a HashMap with size 5, but I only saw 4 elements which gave the OptionalDataException. I now use a synchronized map and don't see the exception anymore (after 1 day of testing, so I don't cheer too loud yet). Definitely get back to us with an update. It would be nice to know that this problem turned out to be caused by the webapp and not Tomcat in some way. - -chris Hi, Today we had to do an update during work hours and all sessions were ok. So I consider this OptionalDataException solved for me. It was a not synchronized Map in the session which is updated more frequently now than in the past and triggered a race condition now. Greetings and thanks for responses and tips, Ronald.
Re: getAllClusterSessions gives OptionalDataException
Op donderdag, 7 juli 2011 18:03 schreef Filip Hanik - Dev Lists devli...@hanik.com: On 6/28/2011 2:31 AM, Konstantin Kolinko wrote: 2011/6/23 Ronald Klopronald-mailingl...@base.nl: Hi, I have an exception when one on my Tomcat nodes restarts. The session are not synced and user complain about being logged out. I was running 6.0.32 and had the problem. Now I'm running a custom build of 6.0.33 from yesterday. I added a little code which prints ' SEVERE: name=user'. The key on which the sync fails while reading the value. I looked into the java code in ObjectInputStream and it looks like some inconsistency in the ObjectStream. I have 4 nodes on Debian 5, sun-java6-jdk 6-22-0lenny1, seen the problem on Tomcat 6.0.29, 6.0.32 and a custom build 6.0.33. I can't reproduce this (yet) on my test environment, so debugging it is difficult without upset customers. Engine name=Catalina defaultHost=xxx.xxx.xxx Realm className=org.apache.catalina.realm.UserDatabaseRealm resourceName=UserDatabase / Cluster className=org.apache.catalina.ha.tcp.SimpleTcpCluster Channel className=org.apache.catalina.tribes.group.GroupChannel Membership className=org.apache.catalina.tribes.membership.McastService port=47727 / /Channel /Cluster Host name=xxx.xxx.xxx appBase=/data/webapps/crm-LIVE/deployed unpackWARs=true autoDeploy=false xmlValidation=false xmlNamespaceAware=true /Host /Engine Can I provide more information? Where should I look. NB: In some previous mails about another problem I thought that might be the reason for my logout problem, that is why I tried 6.0.33-dev. Ronald. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 0, 10, 110}:4000,{10, 0, 10, 110},4000, alive=45370885,id={-34 112 102 -93 -87 -88 77 18 -113 -30 62 8 62 -65 -112 -13 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions INFO: Manager [crm.realworks.nl#]; session state send at 6/23/11 5:49 PM received in 304 ms. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#]: Drop message SESSION-ACCESSED inside GET_ALL_SESSIONS sync phase start date 6/23/11 5:49 PM message date 6/23/11 5:49 PM Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaSession readObject SEVERE: name=user. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager deserializeSessions SEVERE: IOException while loading persisted sessions: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1348) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at java.util.HashMap.readObject(HashMap.java:1029) (...) Looking at ObjectInputStream sourced, the OptionalDataException is thrown when the source stream is truncated. It might be related to the following issue, fixed in Tomcat 7, but never proposed for backport yet: https://issues.apache.org/bugzilla/show_bug.cgi?id=50646 Tribes ByteMessage will get corrupted if message size exceeds the underlying buffer size that's what I thought, but the SessionMessage doesn't use ByteMessage Best regards, Konstantin Kolinko Hi Konstantin, The 'Tribes ByteMessage' issue didn't solve my problem. But. After some fun with debugging Tomcat on my live server (because I couldn't reproduce it in test) it looks like a concurrency bug in my own code. I think I modify a HashMap which is serialized in the session. For some reason I don't get a ConcurrentModificationException, but in the byte[] in DeltaManager.handleALL_SESSION_DATA I had a HashMap with size 5, but I only saw 4 elements which gave the OptionalDataException. I now use a synchronized map and don't see the exception anymore (after 1 day of testing, so I don't cheer too loud yet). Ronald.
Re: getAllClusterSessions gives OptionalDataException
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Ronald, On 7/8/2011 5:33 AM, Ronald Klop wrote: After some fun with debugging Tomcat on my live server (because I couldn't reproduce it in test) it looks like a concurrency bug in my own code. D'oh. I think I modify a HashMap which is serialized in the session. For some reason I don't get a ConcurrentModificationException, but in the byte[] in DeltaManager.handleALL_SESSION_DATA I had a HashMap with size 5, but I only saw 4 elements which gave the OptionalDataException. I now use a synchronized map and don't see the exception anymore (after 1 day of testing, so I don't cheer too loud yet). Definitely get back to us with an update. It would be nice to know that this problem turned out to be caused by the webapp and not Tomcat in some way. - -chris -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.10 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAk4XYMcACgkQ9CaO5/Lv0PCmwACgub9BSbILSjSDFwnMej4p0JrR f2wAnRZ4CmlvaiYfHVaN8oUTx+FWhytb =b7Ol -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: getAllClusterSessions gives OptionalDataException
On 6/28/2011 2:31 AM, Konstantin Kolinko wrote: 2011/6/23 Ronald Klopronald-mailingl...@base.nl: Hi, I have an exception when one on my Tomcat nodes restarts. The session are not synced and user complain about being logged out. I was running 6.0.32 and had the problem. Now I'm running a custom build of 6.0.33 from yesterday. I added a little code which prints ' SEVERE: name=user'. The key on which the sync fails while reading the value. I looked into the java code in ObjectInputStream and it looks like some inconsistency in the ObjectStream. I have 4 nodes on Debian 5, sun-java6-jdk 6-22-0lenny1, seen the problem on Tomcat 6.0.29, 6.0.32 and a custom build 6.0.33. I can't reproduce this (yet) on my test environment, so debugging it is difficult without upset customers. Engine name=Catalina defaultHost=xxx.xxx.xxx Realm className=org.apache.catalina.realm.UserDatabaseRealm resourceName=UserDatabase / Cluster className=org.apache.catalina.ha.tcp.SimpleTcpCluster Channel className=org.apache.catalina.tribes.group.GroupChannel Membership className=org.apache.catalina.tribes.membership.McastService port=47727 / /Channel /Cluster Host name=xxx.xxx.xxx appBase=/data/webapps/crm-LIVE/deployed unpackWARs=true autoDeploy=false xmlValidation=false xmlNamespaceAware=true /Host /Engine Can I provide more information? Where should I look. NB: In some previous mails about another problem I thought that might be the reason for my logout problem, that is why I tried 6.0.33-dev. Ronald. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 0, 10, 110}:4000,{10, 0, 10, 110},4000, alive=45370885,id={-34 112 102 -93 -87 -88 77 18 -113 -30 62 8 62 -65 -112 -13 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions INFO: Manager [crm.realworks.nl#]; session state send at 6/23/11 5:49 PM received in 304 ms. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#]: Drop message SESSION-ACCESSED inside GET_ALL_SESSIONS sync phase start date 6/23/11 5:49 PM message date 6/23/11 5:49 PM Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaSession readObject SEVERE: name=user. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager deserializeSessions SEVERE: IOException while loading persisted sessions: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1348) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at java.util.HashMap.readObject(HashMap.java:1029) (...) Looking at ObjectInputStream sourced, the OptionalDataException is thrown when the source stream is truncated. It might be related to the following issue, fixed in Tomcat 7, but never proposed for backport yet: https://issues.apache.org/bugzilla/show_bug.cgi?id=50646 Tribes ByteMessage will get corrupted if message size exceeds the underlying buffer size that's what I thought, but the SessionMessage doesn't use ByteMessage Best regards, Konstantin Kolinko - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: getAllClusterSessions gives OptionalDataException
2011/6/23 Ronald Klop ronald-mailingl...@base.nl: Hi, I have an exception when one on my Tomcat nodes restarts. The session are not synced and user complain about being logged out. I was running 6.0.32 and had the problem. Now I'm running a custom build of 6.0.33 from yesterday. I added a little code which prints ' SEVERE: name=user'. The key on which the sync fails while reading the value. I looked into the java code in ObjectInputStream and it looks like some inconsistency in the ObjectStream. I have 4 nodes on Debian 5, sun-java6-jdk 6-22-0lenny1, seen the problem on Tomcat 6.0.29, 6.0.32 and a custom build 6.0.33. I can't reproduce this (yet) on my test environment, so debugging it is difficult without upset customers. Engine name=Catalina defaultHost=xxx.xxx.xxx Realm className=org.apache.catalina.realm.UserDatabaseRealm resourceName=UserDatabase / Cluster className=org.apache.catalina.ha.tcp.SimpleTcpCluster Channel className=org.apache.catalina.tribes.group.GroupChannel Membership className=org.apache.catalina.tribes.membership.McastService port=47727 / /Channel /Cluster Host name=xxx.xxx.xxx appBase=/data/webapps/crm-LIVE/deployed unpackWARs=true autoDeploy=false xmlValidation=false xmlNamespaceAware=true /Host /Engine Can I provide more information? Where should I look. NB: In some previous mails about another problem I thought that might be the reason for my logout problem, that is why I tried 6.0.33-dev. Ronald. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 0, 10, 110}:4000,{10, 0, 10, 110},4000, alive=45370885,id={-34 112 102 -93 -87 -88 77 18 -113 -30 62 8 62 -65 -112 -13 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions INFO: Manager [crm.realworks.nl#]; session state send at 6/23/11 5:49 PM received in 304 ms. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#]: Drop message SESSION-ACCESSED inside GET_ALL_SESSIONS sync phase start date 6/23/11 5:49 PM message date 6/23/11 5:49 PM Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaSession readObject SEVERE: name=user. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager deserializeSessions SEVERE: IOException while loading persisted sessions: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1348) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at java.util.HashMap.readObject(HashMap.java:1029) (...) Looking at ObjectInputStream sourced, the OptionalDataException is thrown when the source stream is truncated. It might be related to the following issue, fixed in Tomcat 7, but never proposed for backport yet: https://issues.apache.org/bugzilla/show_bug.cgi?id=50646 Tribes ByteMessage will get corrupted if message size exceeds the underlying buffer size Best regards, Konstantin Kolinko - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: getAllClusterSessions gives OptionalDataException
I double checked. The version of Tomcat and the versions of Java are all the same. Ronald. Op vrijdag, 24 juni 2011 03:25 schreef Filip Hanik - Dev Lists devli...@hanik.com: are there other versions of Apache Tomcat running in the same cluster? Check the logs for what members are joining the cluster, then check what version they are best Filip On 6/23/2011 10:14 AM, Ronald Klop wrote: Hi, I have an exception when one on my Tomcat nodes restarts. The session are not synced and user complain about being logged out. I was running 6.0.32 and had the problem. Now I'm running a custom build of 6.0.33 from yesterday. I added a little code which prints ' SEVERE: name=user'. The key on which the sync fails while reading the value. I looked into the java code in ObjectInputStream and it looks like some inconsistency in the ObjectStream. I have 4 nodes on Debian 5, sun-java6-jdk 6-22-0lenny1, seen the problem on Tomcat 6.0.29, 6.0.32 and a custom build 6.0.33. I can't reproduce this (yet) on my test environment, so debugging it is difficult without upset customers. Engine name=Catalina defaultHost=xxx.xxx.xxx Realm className=org.apache.catalina.realm.UserDatabaseRealm resourceName=UserDatabase / Cluster className=org.apache.catalina.ha.tcp.SimpleTcpCluster Channel className=org.apache.catalina.tribes.group.GroupChannel Membership className=org.apache.catalina.tribes.membership.McastService port=47727 / /Channel /Cluster Host name=xxx.xxx.xxx appBase=/data/webapps/crm-LIVE/deployed unpackWARs=true autoDeploy=false xmlValidation=false xmlNamespaceAware=true /Host /Engine Can I provide more information? Where should I look. NB: In some previous mails about another problem I thought that might be the reason for my logout problem, that is why I tried 6.0.33-dev. Ronald. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 0, 10, 110}:4000,{10, 0, 10, 110},4000, alive=45370885,id={-34 112 102 -93 -87 -88 77 18 -113 -30 62 8 62 -65 -112 -13 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions INFO: Manager [crm.realworks.nl#]; session state send at 6/23/11 5:49 PM received in 304 ms. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#]: Drop message SESSION-ACCESSED inside GET_ALL_SESSIONS sync phase start date 6/23/11 5:49 PM message date 6/23/11 5:49 PM Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaSession readObject SEVERE: name=user. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager deserializeSessions SEVERE: IOException while loading persisted sessions: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1348) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at java.util.HashMap.readObject(HashMap.java:1029) at sun.reflect.GeneratedMethodAccessor23.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1848) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328) at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at org.apache.catalina.ha.session.DeltaSession.readObject(DeltaSession.java:655) at org.apache.catalina.ha.session.DeltaSession.readObjectData(DeltaSession.java:481) at org.apache.catalina.ha.session.DeltaManager.deserializeSessions(DeltaManager.java:745) at org.apache.catalina.ha.session.DeltaManager.handleALL_SESSION_DATA(DeltaManager.java:1583) at org.apache.catalina.ha.session.DeltaManager.messageReceived(DeltaManager.java:1440) at org.apache.catalina.ha.session.DeltaManager.messageDataReceived(DeltaManager.java:1173) at
Re: getAllClusterSessions gives OptionalDataException
are there other versions of Apache Tomcat running in the same cluster? Check the logs for what members are joining the cluster, then check what version they are best Filip On 6/23/2011 10:14 AM, Ronald Klop wrote: Hi, I have an exception when one on my Tomcat nodes restarts. The session are not synced and user complain about being logged out. I was running 6.0.32 and had the problem. Now I'm running a custom build of 6.0.33 from yesterday. I added a little code which prints ' SEVERE: name=user'. The key on which the sync fails while reading the value. I looked into the java code in ObjectInputStream and it looks like some inconsistency in the ObjectStream. I have 4 nodes on Debian 5, sun-java6-jdk 6-22-0lenny1, seen the problem on Tomcat 6.0.29, 6.0.32 and a custom build 6.0.33. I can't reproduce this (yet) on my test environment, so debugging it is difficult without upset customers. Engine name=Catalina defaultHost=xxx.xxx.xxx Realm className=org.apache.catalina.realm.UserDatabaseRealm resourceName=UserDatabase / Cluster className=org.apache.catalina.ha.tcp.SimpleTcpCluster Channel className=org.apache.catalina.tribes.group.GroupChannel Membership className=org.apache.catalina.tribes.membership.McastService port=47727 / /Channel /Cluster Host name=xxx.xxx.xxx appBase=/data/webapps/crm-LIVE/deployed unpackWARs=true autoDeploy=false xmlValidation=false xmlNamespaceAware=true /Host /Engine Can I provide more information? Where should I look. NB: In some previous mails about another problem I thought that might be the reason for my logout problem, that is why I tried 6.0.33-dev. Ronald. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 0, 10, 110}:4000,{10, 0, 10, 110},4000, alive=45370885,id={-34 112 102 -93 -87 -88 77 18 -113 -30 62 8 62 -65 -112 -13 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions INFO: Manager [crm.realworks.nl#]; session state send at 6/23/11 5:49 PM received in 304 ms. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions WARNING: Manager [crm.realworks.nl#]: Drop message SESSION-ACCESSED inside GET_ALL_SESSIONS sync phase start date 6/23/11 5:49 PM message date 6/23/11 5:49 PM Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaSession readObject SEVERE: name=user. Jun 23, 2011 5:49:47 PM org.apache.catalina.ha.session.DeltaManager deserializeSessions SEVERE: IOException while loading persisted sessions: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1348) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at java.util.HashMap.readObject(HashMap.java:1029) at sun.reflect.GeneratedMethodAccessor23.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1848) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328) at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350) at org.apache.catalina.ha.session.DeltaSession.readObject(DeltaSession.java:655) at org.apache.catalina.ha.session.DeltaSession.readObjectData(DeltaSession.java:481) at org.apache.catalina.ha.session.DeltaManager.deserializeSessions(DeltaManager.java:745) at org.apache.catalina.ha.session.DeltaManager.handleALL_SESSION_DATA(DeltaManager.java:1583) at org.apache.catalina.ha.session.DeltaManager.messageReceived(DeltaManager.java:1440) at org.apache.catalina.ha.session.DeltaManager.messageDataReceived(DeltaManager.java:1173) at org.apache.catalina.ha.session.ClusterSessionListener.messageReceived(ClusterSessionListener.java:92) at org.apache.catalina.ha.tcp.SimpleTcpCluster.messageReceived(SimpleTcpCluster.java:901) at org.apache.catalina.ha.tcp.SimpleTcpCluster.messageReceived(SimpleTcpCluster.java:882) at org.apache.catalina.tribes.group.GroupChannel.messageReceived(GroupChannel.java:269) at