Bug 58289 - request.getRemoteAddr() sometimes returning IP address from the previous request
Summary: request.getRemoteAddr() sometimes returning IP address from the previous request
Status: RESOLVED WORKSFORME
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 7.0.54
Hardware: PC All
: P2 normal (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-08-27 10:13 UTC by Tim Hunt
Modified: 2016-06-15 14:09 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Tim Hunt 2015-08-27 10:13:33 UTC
This is exactly the same symptoms as Bug 51872, which was fixed in 7.0.22 (see comment 11). However, there are following comments there which say other people are still seeing the problem, presumably due to other causes.

We are currently seeing this bug in Tomcat 7.0.54, running under RHEL 7. I am doing what it says in comment 16 of Bug 51872 and creating a new issue. I do not have any code for a minimal reproducible test-case, but I can definitely reproduce the issue in my application as follows:

We have Tomcat set up behind Apache acting as a proxy, which I believe is quite a common set-up. I don't know if that is signifcant for this bug.

To reproduce the problem, send a high volume of

* requests for http://example.com/servlet/url1 from IP address 1, and
* requests for http://example.com/servlet/url2 from IP address 2.

Then, if you look in the Apache access logs, all the requests are logged with the correct IP address (IP address 1 or 2).

However, in the Tomcat access logs (e.g. /var/log/tomcat/localhost_access_log.2015-08-25.txt) a small proportion of the requests (just under 5%) get the wrong IP address logged (IP1 when it should be IP2, or vice versa). Most of the requests are logged with the correct IP.

Corresponding to this, in my application request.getRemoteAddr() returns the same IP address that is in the Tomcal logs (unsuprising). That then causes the application errors that is what lead me to start investigating this.

We have been able to work-around this problem by setting org.apache.catalina.connector.RECYCLE_FACADES=true. With that setting the bug does not occur.
Comment 1 Mark Thomas 2015-08-27 19:04:38 UTC
(In reply to Tim Hunt from comment #0)

> We have been able to work-around this problem by setting
> org.apache.catalina.connector.RECYCLE_FACADES=true. With that setting the
> bug does not occur.

That indicates that this is an application bug. It looks like you have something retaining a reference to a request and calling request.getRemoteAddr() after the processing of the request has completed and the request has been recycled.

With org.apache.catalina.connector.RECYCLE_FACADES=true I'd expect to see NPEs at the point where the request is accessed illegally. Do you have any NPEs in your logs? If not, might the application be swallowing them?
Comment 2 Tim Hunt 2015-08-27 19:23:41 UTC
Thanks for your response.

I understand what you are saying about request.getRemoteAddr(), but ...

1. As I say above, the wrong IP address is getting logged in the Tomcat access logs. Surely my application code should not affect what is logged there.

2. My application code is not quite as simple as:

protected void doGet(HttpServletRequest request, HttpServletResponse response)
        throws ServletException, IOException {

    if (!isAllowed(request.getRemoteAddr())) {			
        sendError(request, response, HttpServletResponse.SC_FORBIDDEN, 
                "You are not authorised to access this URL.");
    }

    sendResponse(request, response);
}

but it is not fundamentally more complex than that. Also, there is no where in the code where we store request or response. They are just used as local variables in the various methods the generate the response, and when they go out of scope they are left for the garbage collector.

All errors are logged reliably. One of the oversimplifications I made in the code snipped above is the big try catch finally block the surrounds the whole of doGet and doPost. Because of trying to understand this bug, I have been grepping our logs for words like 'error' before and after the config change, and after the config change there were no null pointer exceptions.

I will agree that it is very mysterious. Still, I wanted to get this bug report filed, because in all my Googling for possible explanations, I only found that one closed bug that offered any clues.
Comment 3 Mark Thomas 2015-08-27 20:29:26 UTC
(In reply to Tim Hunt from comment #2)

> 1. As I say above, the wrong IP address is getting logged in the Tomcat
> access logs. Surely my application code should not affect what is logged
> there.

If you access a request object outside of the normal request lifecycle you have the potential to cause all sorts of problems.

> 2. My application code is not quite as simple as:
> 
> protected void doGet(HttpServletRequest request, HttpServletResponse
> response)
>         throws ServletException, IOException {
> 
>     if (!isAllowed(request.getRemoteAddr())) {			
>         sendError(request, response, HttpServletResponse.SC_FORBIDDEN, 
>                 "You are not authorised to access this URL.");
>     }
> 
>     sendResponse(request, response);
> }
> 
> but it is not fundamentally more complex than that. Also, there is no where
> in the code where we store request or response. They are just used as local
> variables in the various methods the generate the response, and when they go
> out of scope they are left for the garbage collector.

OK. That makes a Tomcat bug more likely.

> All errors are logged reliably. One of the oversimplifications I made in the
> code snipped above is the big try catch finally block the surrounds the
> whole of doGet and doPost. Because of trying to understand this bug, I have
> been grepping our logs for words like 'error' before and after the config
> change, and after the config change there were no null pointer exceptions.

That is consistent with this being a Tomcat bug.

> I will agree that it is very mysterious. Still, I wanted to get this bug
> report filed, because in all my Googling for possible explanations, I only
> found that one closed bug that offered any clues.

You did the right thing.

I have a couple of further questions:
1. How are you proxing requests from httpd to Tomcat? mod_jk, mod_proxy_http, mod_proxy_ajp?
2. Which version of httpd (and mod_jk if you are using that)?
3. Which connector are you using on the Tomcate side? HTTP/AJP? BIO/NIO/APR?

Finally, if you are able to reduce this to a simple WAR that demonstrates the issue (ideally wth a servelt / JSP as simple as the code above) then that would really help us track this down. Without a test case the only option to figure what is going on is code inspection.
Comment 4 Tim Hunt 2015-08-27 21:09:29 UTC
My role is application developer, and we have other people who handle the details of the server set-up. I will try to get them to answer the technical questions. However, I am about to go on holiday for about 10 days, so don't expect a quick response.
Comment 5 Mark Thomas 2016-06-15 14:09:47 UTC
Can't reproduce and not reproduction information provided after 9+ months.