Bug 51872 - request.getRemoteAddr() sometimes returning IP address from the previous request
Summary: request.getRemoteAddr() sometimes returning IP address from the previous request
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 7.0.20
Hardware: PC Linux
: P2 blocker (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-09-22 17:52 UTC by charlie
Modified: 2015-09-17 14:52 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description charlie 2011-09-22 17:52:57 UTC
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'
Comment 1 Konstantin Kolinko 2011-09-22 18:17:11 UTC
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?
Comment 2 Mark Thomas 2011-09-22 18:22:18 UTC
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?
Comment 3 charlie 2011-09-22 18:36:22 UTC
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]
Comment 4 charlie 2011-09-22 19:35:41 UTC
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();
    }
Comment 5 charlie 2011-09-22 19:53:10 UTC
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();
    }
Comment 6 Mark Thomas 2011-09-22 20:28:06 UTC
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.
Comment 7 Mark Thomas 2011-09-22 21:55:46 UTC
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.
Comment 8 Mark Thomas 2011-09-23 08:09:32 UTC
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);
Comment 9 charlie 2011-09-23 15:14:21 UTC
Yes, RECYCLE_FACADES=true didn't work for us.
We will try the patch from the comment 8 and let you know.
Thanks.
Comment 10 charlie 2011-09-24 03:44:49 UTC
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().
Comment 11 Mark Thomas 2011-09-27 20:19:03 UTC
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.
Comment 12 Konstantin Kolinko 2011-10-19 07:18:24 UTC
Fixed in 6.0 with r1185998 and will be in 6.0.34 onwards.
Comment 13 Bart Hanlon 2011-11-03 22:38:12 UTC
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.
Comment 14 Mark Thomas 2011-11-03 22:41:37 UTC
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.
Comment 15 Michael Hauck 2012-03-15 15:08:24 UTC
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!
Comment 16 Mark Thomas 2012-03-15 19:07:55 UTC
(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
Comment 17 Tim Hunt 2015-09-17 14:52:22 UTC
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.