request.getRemoteAddr() sometimes returning IP address from the previous request. We have compared the IP address returned from the getRemoteHost() and from the headers with getRemoteAddr() and getRemoteAddr is returning wrong IP address. We believe that this may come from the "pooled" request objects where it is sometimes sees the previous value of the remote IP. The problem doesn't occur all the time. We are heavily relying on the getRemoteAddr to verify the remote client for some of our authentication. Can this be fixed? 2011-09-22 16:49:55,713 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve invoked 2011-09-22 16:49:55,826 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve request.getInfo(): org.apache.coyote.catalina.CoyoteRequest/1.0 2011-09-22 16:49:56,013 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve request.getRemoteAddr(): 98.138.85.230 2011-09-22 16:49:56,014 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve request.getRemoteHost(): web120016.mail.ne1.yahoo.com [][~]$ nslookup web120016.mail.ne1.yahoo.com Server: 10.72.226.8 Address: 10.72.226.8#53 Name: web120016.mail.ne1.yahoo.com Address: 98.138.85.143 2011-09-22 16:49:56,014 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve request.getRequestedSessionId(): null 2011-09-22 16:49:56,015 DEBUG [yjava.tomcat.valves.YahooConnectionValve] THREADID:1262 YahooConnectionValve request.getHeader(): accept:*/* host:ls100.mail.vip.ne1.yahoo.com:4080 content-type:application/x-ypy yahoo-app-auth:v=1;a=yahoo.mail.acl.yca.lsg-prod;h=98.138.85.143;t=1319282225; content-length:574 2011-09-22 16:49:56,015 DEBUG [yjava.filter.address.RemoteIPTranslator] THREADID:1262 Got remote address '98.138.85.230' and port '46663'
Is it with HTTP connector or AJP connector? Is it standalone Tomcat, or fronted by some other HTTP server? What connector implementations are you observing this with (BIO/NIO/APR)? It is shown in the logs when Tomcat starts up. Do you have RemoteIpValve configured? Is it reproducible with a simple web application?
I've double checked the Tomcat 7 code and remote host and remote address are recycled at exactly the same point. If one failed to recycle, so would the other and both would be wrong. I am therefore doubtful that this is a Tomcat bug. To add to Konstantin's questions, how confident are you that the IP address in the auth header is correct?
It's standalone. No mod_jk. We have ran various packet captures to verify that the IP address in the auth header is correct. Since the IP address in the header and the IP address from the getRemoteHost match, we believe that that getRemoteAddr is wrong. Difficult part of this is that we can not reproduce this in our test environments. Connector: <Connector allowTrace="true" asyncTimeout="10000" enableLookups="true" maxPostSize="2097152" maxSavePostSize="4096" parseBodyMethods="POST" redirectPort="-1" scheme="http" secure="false" URIEncoding="UTF-8" xpoweredBy="false" acceptCount="100" acceptorThreadCount="1" address="0.0.0.0" bindOnInit="true" socketBuffer="9000" compressableMimeType="text/html,text/xml,text/plain" compression="off" compressionMinSize="2048" connectionLinger="-1" connectionTimeout="60000" connectionUploadTimeout="60000" disableUploadTimeout="true" executor="" keepAliveTimeout="20000" maxConnections="200" maxHttpHeaderSize="8192" maxKeepAliveRequests="1" maxThreads="200" maxTrailerSize="8192" minSpareThreads="10" noCompressionUserAgents="" processorCache="200" port="4080" restrictedUserAgents="" server="Apache" SSLEnabled="false" tcpNoDelay="true" sslImplemenationName="org.apache.tomcat.util.net.jsse.JSSEImplementation" clientCertProvider="" keyPass="changeit" sslEnabledProtocols="" trustManagerClassName="" trustMaxCertLength="5" truststoreAlgorithm=""/> Valves: <Valve className="yjava.tomcat.valves.YahooConnectionValve"/> <Valve className="com.yahoo.yjava.YahooLogValve" directory="/home/y/logs/yjava_tomcat/" yahooOpts="gmrswZX" prefix="access." resolveHosts="false" suffix=".log" rotatable="true" buffered="false" fileDateFormat="yyyy-MM-dd.HH"/> More debugs. 2011-09-22 18:12:53,576 INFO [org.apache.coyote.http11.Http11Protocol] Starting ProtocolHandler ["http-bio-/0.0.0.0-4080"] 2011-09-22 18:12:53,586 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [default] in Context [] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,586 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [jsp] in Context [] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,586 DEBUG [org.apache.catalina.connector.MapperListener] Register Context [] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,586 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [default] in Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [jsp] in Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [jersey] in Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [noop] in Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register Wrapper [requestparams] in Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register Context [/yjava_ws_examples_filters] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:12:53,587 DEBUG [org.apache.catalina.connector.MapperListener] Register host [localhost] at domain [null] for connector [Connector[HTTP/1.1-4080]] 2011-09-22 18:15:06,149 DEBUG [org.apache.coyote.http11.Http11Protocol] Register Catalina:type=RequestProcessor,worker="http-bio-/0.0.0.0-4080",name=HttpRequest1 2011-09-22 18:15:06,226 DEBUG [org.apache.catalina.connector.CoyoteAdapter] The variable [uriBC] has value [/yjava_ws_examples_filters/v1/yiv/hello] 2011-09-22 18:15:06,226 DEBUG [org.apache.catalina.connector.CoyoteAdapter] The variable [semicolon] has value [-1] 2011-09-22 18:15:06,226 DEBUG [org.apache.catalina.connector.CoyoteAdapter] The variable [enc] has value [UTF-8]
I don't see remoteAddrMB being recycled. private MessageBytes remoteAddrMB = MessageBytes.newInstance(); // -------------------- Recycling -------------------- public void recycle() { bytesRead=0; contentLength = -1; contentTypeMB = null; charEncoding = null; headers.recycle(); serverNameMB.recycle(); serverPort=-1; localPort = -1; remotePort = -1; available = 0; cookies.recycle(); parameters.recycle(); unparsedURIMB.recycle(); uriMB.recycle(); decodedUriMB.recycle(); queryMB.recycle(); methodMB.recycle(); protoMB.recycle(); schemeMB.recycle(); instanceId.recycle(); remoteUser.recycle(); authType.recycle(); attributes.clear(); }
Where in Tomcat 6, its being recycled. http://svn.apache.org/repos/asf/tomcat/tc6.0.x/trunk/java/org/apache/tomcat/util/http/BaseRequest.java MessageBytes remoteAddr = MessageBytes.newInstance(); /** * Recycles this object and readies it further use. */ public void recycle() { method.recycle(); protocol.recycle(); requestURI.recycle(); remoteAddr.recycle(); remoteHost.recycle(); serverName.recycle(); serverPort = 80; remoteUser.recycle(); authType.recycle(); queryString.recycle(); authorization.recycle(); scheme = SCHEME_HTTP; secure = false; contentLength = 0; contentType.recycle(); headers.recycle(); cookies.recycle(); attributes.clear(); tomcatInstanceId.recycle(); }
I don't think that is it. The remoteHost MessageBytes aren't recycled either in Tomcat 7 and that doesn't have the same issue. Also, I don't see how the remoteAddr MessageBytes could be accessed without first having been set. I am extremely reluctant to start changing code without a clear explanation of why making the change will fix the observed problem. I don't mind if I can't reproduce the problem but there does need to be a logical explanation of why the change fixes the observed issue.
If the application is retaining a reference to the request object there is a possible race condition that could lead to the behaviour you see here. If during the call to AbstractHttp11Processor.recycle() - triggered at the end of request processing - if there is a call to Request.getRemoteAddr() after AbstractHttp11Processor.remoteAddr has been set to null but before recycleInternal() is called then remoteAddr will end up being populated with the IP address of the previous connection. The way to test this is to set set the following system property: org.apache.catalina.connector.RECYCLE_FACADES=true Please let us know how you get on with testing using this setting.
Looking at this again this morning, if the problem is in a Valve RECYCLE_FACADES won't help since Valves have direct access to the Request object rather than using the Facade. The patch below can be used to see if a Valve (or similar) is accessing the request after it has been recycled. In addition to logging an error, it can either return null or throw an exception if this happens. Just comment out the one you don't want. Index: java/org/apache/catalina/connector/Request.java =================================================================== --- java/org/apache/catalina/connector/Request.java (revision 1174344) +++ java/org/apache/catalina/connector/Request.java (working copy) @@ -508,7 +508,8 @@ } mappingData.recycle(); - + remoteAddr = null; + if (Globals.IS_SECURITY_ENABLED || Connector.RECYCLE_FACADES) { if (facade != null) { facade.clear(); @@ -1263,6 +1264,12 @@ */ @Override public String getRemoteAddr() { + if (mappingData.host == null) { + String msg = "Access to Request at invalid point in lifecycle"; + log.error(msg); + // throw new IllegalStateException(msg); + return null; + } if (remoteAddr == null) { coyoteRequest.action (ActionCode.REQ_HOST_ADDR_ATTRIBUTE, coyoteRequest);
Yes, RECYCLE_FACADES=true didn't work for us. We will try the patch from the comment 8 and let you know. Thanks.
Mark, After applying the patch from comment 8, we get these in our logs (quite a alot). But we no longer have our problem of getting the previous IP address. 03:17:04,436 ERROR [Request] THREADID:292###PATCH###: Access to Request at invalid point in lifecycle. Returning null for getRemoteAddr().
Fixed in trunk and 7.0.x and will be included in 7.0.22 onwards. I also fixed a related issue discovered during testing that meant requests with multiple errors could trigger multiple entries in the access log.
Fixed in 6.0 with r1185998 and will be in 6.0.34 onwards.
We are seeing the same issue when Tomcat 7.0.22 is under heavier load (in our case servicing >30 incoming POST requests per second). request.getRemoteAddr() is periodically (though not consistently) returning an IP address from the previous request.
This issue has been fixed. There are multiple possible causes of the symptom described here and the vast majority of them are application bugs. Please follow-up on the users-mailing list.
Mark, we upgraded from 6.0.29 to 7.0.23 and have exactly the same problem. I can certainly exclude an application bug. This method is fundamental!
(In reply to comment #15) > Mark, > > we upgraded from 6.0.29 to 7.0.23 and have exactly the same problem. I can > certainly exclude an application bug. This method is fundamental! Again. *This* issue has been fixed. There are multiple possible causes of the symptom described here and the vast majority of them are application bugs. Please follow-up on the users-mailing list. Feel free to create a new bug (since this specific issue is fixed) once you have one of the following: - an explanation based on an analysis of the source code of why requests are getting mixed up - a reproducible test case that demonstrates the issue
I just want to note that, like others, we are still seeing these symptoms, and I created bug 58289. I have not yet had time to create a minimal test-case, but I want to if I can.