Return-Path: Delivered-To: apmail-tomcat-users-archive@www.apache.org Received: (qmail 81634 invoked from network); 8 Nov 2005 10:32:36 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199) by minotaur.apache.org with SMTP; 8 Nov 2005 10:32:36 -0000 Received: (qmail 8687 invoked by uid 500); 8 Nov 2005 10:32:21 -0000 Delivered-To: apmail-tomcat-users-archive@tomcat.apache.org Received: (qmail 8465 invoked by uid 500); 8 Nov 2005 10:32:20 -0000 Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "Tomcat Users List" Delivered-To: mailing list users@tomcat.apache.org Received: (qmail 8454 invoked by uid 99); 8 Nov 2005 10:32:19 -0000 Received: from asf.osuosl.org (HELO asf.osuosl.org) (140.211.166.49) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 08 Nov 2005 02:32:19 -0800 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (asf.osuosl.org: domain of jak-tomcat-user@m.gmane.org designates 80.91.229.2 as permitted sender) Received: from [80.91.229.2] (HELO ciao.gmane.org) (80.91.229.2) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 08 Nov 2005 02:32:13 -0800 Received: from root by ciao.gmane.org with local (Exim 4.43) id 1EZQkc-0005Cl-Gj for users@tomcat.apache.org; Tue, 08 Nov 2005 11:30:50 +0100 Received: from olve.intermedia.uib.no ([129.177.28.77]) by main.gmane.org with esmtp (Gmexim 0.1 (Debian)) id 1AlnuQ-0007hv-00 for ; Tue, 08 Nov 2005 11:30:50 +0100 Received: from olve.hansen by olve.intermedia.uib.no with local (Gmexim 0.1 (Debian)) id 1AlnuQ-0007hv-00 for ; Tue, 08 Nov 2005 11:30:50 +0100 X-Injected-Via-Gmane: http://gmane.org/ To: users@tomcat.apache.org From: Olve Hansen Subject: session replication errors Date: Tue, 08 Nov 2005 11:59:54 +0100 Organization: InterMedia Bergen - Aksis / Unifob AS Lines: 286 Message-ID: <1131447594.11709.15.camel@localhost.localdomain> Mime-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha1; protocol="application/pgp-signature"; boundary="=-+PK8h/uGN8h9Pp+aLg3g" X-Complaints-To: usenet@sea.gmane.org X-Gmane-NNTP-Posting-Host: olve.intermedia.uib.no X-Mailer: Evolution 2.4.1 Sender: news X-Virus-Checked: Checked by ClamAV on apache.org X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N --=-+PK8h/uGN8h9Pp+aLg3g Content-Type: text/plain Content-Transfer-Encoding: quoted-printable Hi, First I must congratulate on the improvements of the clustering docs! Now I don't have to guess nearly as much as before when trying to set up clustering. :-) But I still have some troubles regarding clustering. We have a webapp clustered over three tomcats, all on the same machine, load balanced by mod_jk in an Apache frontend, using sticky lb, session replication by fastasyncqueue.=20 It seems OK - no session dropouts in sticky mode, we can turn on and off tomcats as we please. But, in the logs, we see numerous: SEVERE: TCP Worker thread in cluster caught 'java.io.IOException: Connection reset by peer' closing channel java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207) at o.a.c.cluster.tcp.TcpReplicationThread.drainChannel(TcpReplicationThread.ja= va:125) at o.a.c.cluster.tcp.TcpReplicationThread.run(TcpReplicationThread.java:69) I am trying to track these down, as they are marked as SEVERE. The tomcats sits on a Red Hat Linux server. It is configured with two networks, one open to the world, and firewalled, the other is internal, and is fully open. The internal net is used for clustering, db-access, and mod_jk connections. How severe are these? Can they be a result of two near concurrent requests, and the second request cancels the serialisation of the first session object? If not, where should I start to look? Log files and cluster setup follows: cluster part of server.xml (only tcpListenPort differs among our configurations): =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D =09 =09 =09 Logs demonstrating the steps toward exceptions: =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D #######Request #1, trying to access home page, redirected to login page: #######Access log from apache: i.p.add.ress - - [07/Nov/2005:11:11:00 +0100] "GET /npweb/t-app HTTP/1.1" 302 - i.p.add.ress - - [07/Nov/2005:11:11:00 +0100] "GET /npweb/t-app?service=3Dexternal/bitecore.loginPage HTTP/1.1" 200 4633 i.p.add.ress - - [07/Nov/2005:11:11:00 +0100] "GET /favicon.ico HTTP/1.1" 404 288 #######Tail from tomcat logs: =3D=3D> tomcat1/logs/catalina.out <=3D=3D Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:11:00 AM 1 - B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260068 Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:11:00 AM 0 - B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260072 [np-norway] INFO [TP-Processor29] BiteEngine.registerTestFormatConfigs(91) | registering all test format configs [np-norway] INFO [TP-Processor29] BiteEngine.registerTestFormatConfigs(108) | TOTALLY REGISTERED 12 TEST FORMAT CONFIGS IN SYSTEM Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:11:00 AM 0 - B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260109 =3D=3D> tomcat2/logs/catalina.out <=3D=3D Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 0 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260068 true Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 1 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260072 true Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 0 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260109 true =3D=3D> tomcat3/logs/catalina.out <=3D=3D Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 0 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260068 true Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 1 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260072 true Nov 7, 2005 11:11:00 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:11:00 AM 1 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358260109 true #######Request #2 (after login): #######Access log from apache: i.p.add.ress - - [07/Nov/2005:11:12:03 +0100] "POST /npweb/j_acegi_security_check HTTP/1.1" 302 - i.p.add.ress - - [07/Nov/2005:11:12:03 +0100] "GET /npweb/t-app HTTP/1.1" 200 6454 i.p.add.ress - - [07/Nov/2005:11:12:05 +0100] "GET /favicon.ico HTTP/1.1" 404 288 #######Tail from tomcat logs: =3D=3D> tomcat1/logs/catalina.out <=3D=3D [np-norway] INFO [TP-Processor29] LoggerListener.onApplicationEvent(125) | Authentication success for user: UserName; details: net.sf.acegisecurity.ui.WebAuthenticationDetails@107513d: RemoteIpAddress: i.p.add.ress; SessionId: B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc1 Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:12:03 AM 2 - B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358323369 =3D=3D> tomcat2/logs/catalina.out <=3D=3D Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.TcpReplicationThread run SEVERE: TCP Worker thread in cluster caught 'java.io.IOException: Connection reset by peer' closing channel java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207) at org.apache.catalina.cluster.tcp.TcpReplicationThread.drainChannel(TcpReplic= ationThread.java:125) at org.apache.catalina.cluster.tcp.TcpReplicationThread.run(TcpReplicationThre= ad.java:69) Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:03 AM 0 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358323369 true Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:12:03 AM 2 - 55AB686217BC200D0D6F026EEC3FA5C7.bserv2tc2-EXPIRED-MSG =3D=3D> tomcat3/logs/catalina.out <=3D=3D Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:03 AM 1 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358323369 true Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.TcpReplicationThread run SEVERE: TCP Worker thread in cluster caught 'java.io.IOException: Connection reset by peer' closing channel java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207) at org.apache.catalina.cluster.tcp.TcpReplicationThread.drainChannel(TcpReplic= ationThread.java:125) at org.apache.catalina.cluster.tcp.TcpReplicationThread.run(TcpReplicationThre= ad.java:69) Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:03 AM 1 192.168.5.112:4,002 55AB686217BC200D0D6F026EEC3FA5C7.bserv2tc2-EXPIRED-MSG true =3D=3D> tomcat1/logs/catalina.out <=3D=3D Nov 7, 2005 11:12:03 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:03 AM 0 192.168.5.112:4,002 55AB686217BC200D0D6F026EEC3FA5C7.bserv2tc2-EXPIRED-MSG true Nov 7, 2005 11:12:04 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logSendMessage INFO: SEND Nov 7, 2005:11:12:04 AM 0 - B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358324900 =3D=3D> tomcat2/logs/catalina.out <=3D=3D Nov 7, 2005 11:12:04 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:04 AM 1 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358324900 true =3D=3D> tomcat3/logs/catalina.out <=3D=3D Nov 7, 2005 11:12:04 AM org.apache.catalina.cluster.tcp.SimpleTcpCluster logReceiveMessage INFO: RECEIVE Nov 7, 2005:11:12:04 AM 0 192.168.5.112:4,001 B07DBFF28ACB2BAC0F28FE9DAC65A69B.bserv2tc11131358324900 true --=-+PK8h/uGN8h9Pp+aLg3g Content-Type: application/pgp-signature; name=signature.asc Content-Description: Dette er en digitalt signert meldingsdel -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux) iD8DBQBDcIUqAtZqQquHhqARAqYNAJ9TfjkNGda2M0ztTys1uUvectAJagCeMzRk YuWGu6eeq+iV15LGtE/dbOo= =4xBv -----END PGP SIGNATURE----- --=-+PK8h/uGN8h9Pp+aLg3g--