You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by "Darius D." <da...@gmail.com> on 2011/09/14 09:34:13 UTC

Request params randomly null in servlet(s)

Hi,

we have a problem of request params beeing null in servlets where it
shouldn't be ( post or get, in get we can even see that
request.getQueryString() is fine, but params are null).

It is more pronounced when using dedicated thread executor, moving to
threads provided by connector itself (with maxThreads="500" option using NIO
) seems to be lowering counts of errors. 


Atm we are seeing 3 modes of failure in our tomcat setup ( nginx reverse
proxy -> tomcat with NIO connector )


1)
SEVERE: Error finishing response
java.lang.NullPointerException

and/or

SEVERE: Error processing request
java.lang.NullPointerException

in logs. ( could be some app problem, but still shady, as no stack trace is
given, like if exception object is gone itself??? )

2) Sometimes we get 502 (from nginx, that got upstream error) like Rakesh in
other thread, from servlets that should be fine ( result of NPE in real
strange places ).

3) And most scary ones are the following:

2011 09 13 14:18:20.568 WARN  Servlet  - error response: error=no action
query: [type=groupsChangedAction&v=1315912033175] content type:null
protocol: HTTP/1.0 length:-1 character encoding: null  GET
2011 09 13 14:18:20.937 WARN  Servlet  - error response: error=no action
query: [type=groupsChangedAction&v=1315912699092] content type:null
protocol: HTTP/1.0 length:-1 character encoding: null  GET

In tomcat access log they are shown as:
127.0.0.1 - - [13/Sep/2011:14:18:20 +0300] "GET
/ourapp/servlet/Servlet?type=groupsChangedAction&v=1315912033175 HTTP/1.0"
200 15
127.0.0.1 - - [13/Sep/2011:14:18:20 +0300] "GET
/ourapp/servlet/Servlet?type=groupsChangedAction&v=1315912699092 HTTP/1.0"
200 15

So as you can see, tomcat got that GET reqest with type and v params like it
gets and processes thousands others.

Servlet code looks like:
private void doProcess(HttpServletRequest request, HttpServletResponse
response) throws IOException {
                HttpSession session = request.getSession();
                if (session != null) {

                        String action = request.getParameter("type");
                        logger.debug("action: " + action);
                       
                        if (action == null) {

                                printError(request, response,"error=no
action");
....

        private void printError(HttpServletRequest request,
HttpServletResponse response, String error) throws IOException {
                logger.warn("error response: " + error + " ip: "  +
request.getRemoteAddr() + " query: [" + request.getQueryString() + "]" + "
content type:" + request.getContentType() + " protocol: " +
request.getProtocol() +  " length:" + request.getContentLength() + "
character encoding: " + request.getCharacterEncoding() + "  " +
request.getMethod());
           
                response.setContentType("text/plain");
                PrintWriter out = response.getWriter();
                out.print(error);
                out.flush();
                out.close();
        }

It happens several times in a day in bursts ( GC collecting something?).


So really puzzling and random error, tomcat got proper request as shown in
access logs (and even request.getQueryString() is valid :) ) , processed
request from same user 5s ago, will process one more 5s later, but somehow
request is NULL??? Now we handle it by retrying, but such random NULL is
fatal for other servlets and services that throw NPEs and it seems that some
tomcat code is affected too with (1).


I'd grateful if some smart guys could look into this problem and willing to
provide any other info.


Only connector running is:
    <Connector port="8080"
protocol="org.apache.coyote.http11.Http11NioProtocol"
               connectionTimeout="20000"
               enableLookups="false"
               acceptCount="1000"
               maxThreads="500"
               maxPostSize="10485760"
                />

Also using 
<Valve className="org.apache.catalina.valves.RemoteIpValve"
        protocolHeader="X-Forwarded-Proto" />


BR,

Darius. 




-- 
View this message in context: http://old.nabble.com/Request-params-randomly-null-in-servlet%28s%29-tp32461421p32461421.html
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Re: Request params randomly null in servlet(s)

Posted by "Darius D." <da...@gmail.com>.

Pid * wrote:
> 
> 
> Exactly which version of Tomcat are you running?
>  
> 


Latest, 7.0.21.

-- 
View this message in context: http://old.nabble.com/Request-params-randomly-null-in-servlet%28s%29-tp32461421p32474158.html
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Re: Request params randomly null in servlet(s)

Posted by Pid <pi...@pidster.com>.
On 15/09/2011 14:46, Darius D. wrote:
> 
> 
> 
> Pid * wrote:
>>
>>
>> What is your server.xml config?  (please remove comments, passwords etc
>> & post it inline, in the response)
>>  
>>
> 
> Here it is, nothing special ( except usage of RemoteIpValve ). Thanks for
> looking into this problem.
> 
> 
> <?xml version='1.0' encoding='utf-8'?>
> <Server port="8005" shutdown="SHUTDOWN">
>   <Listener className="org.apache.catalina.core.AprLifecycleListener"
> SSLEngine="on" />
>   <Listener className="org.apache.catalina.core.JasperListener" />
>   <Listener
> className="org.apache.catalina.core.JreMemoryLeakPreventionListener"/>
>   <Listener
> className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener" />
>   <Listener
> className="org.apache.catalina.core.ThreadLocalLeakPreventionListener" />
> 
> 
>     <Resource name="UserDatabase" auth="Container"
>               type="org.apache.catalina.UserDatabase"
>               description="User database that can be updated and saved"
>               factory="org.apache.catalina.users.MemoryUserDatabaseFactory"
>               pathname="conf/tomcat-users.xml" />
>   </GlobalNamingResources>
> 
> 
>   <Service name="Catalina">
> 
>     <Connector port="8080"
> protocol="org.apache.coyote.http11.Http11NioProtocol"
>                connectionTimeout="20000"
>                enableLookups="false"
>                acceptCount="1000"
>                maxThreads="500"
>                maxPostSize="10485760"
>                 /> 
> 
>     <Engine name="Catalina" defaultHost="localhost">
> 
>       <Realm className="org.apache.catalina.realm.LockOutRealm">
>       <Realm className="org.apache.catalina.realm.UserDatabaseRealm"
>                resourceName="UserDatabase"/>
>       </Realm>
> 
>       <Host name="localhost"  appBase="webapps"
>             unpackWARs="true" autoDeploy="true">
> 
>         <Valve className="org.apache.catalina.valves.RemoteIpValve"
>         protocolHeader="X-Forwarded-Proto" />
> 
>         <Valve className="org.apache.catalina.valves.AccessLogValve"
> directory="logs"
>                prefix="localhost_access_log." suffix=".txt"
>                pattern="%h %l %u %t &quot;%r&quot; %s %b"
> resolveHosts="false"/>
> 
>       </Host>
>     </Engine>
>   </Service>
> </Server>

Exactly which version of Tomcat are you running?


p



Re: Request params randomly null in servlet(s)

Posted by "Darius D." <da...@gmail.com>.


Pid * wrote:
> 
> 
> What is your server.xml config?  (please remove comments, passwords etc
> & post it inline, in the response)
>  
> 

Here it is, nothing special ( except usage of RemoteIpValve ). Thanks for
looking into this problem.


<?xml version='1.0' encoding='utf-8'?>
<Server port="8005" shutdown="SHUTDOWN">
  <Listener className="org.apache.catalina.core.AprLifecycleListener"
SSLEngine="on" />
  <Listener className="org.apache.catalina.core.JasperListener" />
  <Listener
className="org.apache.catalina.core.JreMemoryLeakPreventionListener"/>
  <Listener
className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener" />
  <Listener
className="org.apache.catalina.core.ThreadLocalLeakPreventionListener" />


    <Resource name="UserDatabase" auth="Container"
              type="org.apache.catalina.UserDatabase"
              description="User database that can be updated and saved"
              factory="org.apache.catalina.users.MemoryUserDatabaseFactory"
              pathname="conf/tomcat-users.xml" />
  </GlobalNamingResources>


  <Service name="Catalina">

    <Connector port="8080"
protocol="org.apache.coyote.http11.Http11NioProtocol"
               connectionTimeout="20000"
               enableLookups="false"
               acceptCount="1000"
               maxThreads="500"
               maxPostSize="10485760"
                /> 

    <Engine name="Catalina" defaultHost="localhost">

      <Realm className="org.apache.catalina.realm.LockOutRealm">
      <Realm className="org.apache.catalina.realm.UserDatabaseRealm"
               resourceName="UserDatabase"/>
      </Realm>

      <Host name="localhost"  appBase="webapps"
            unpackWARs="true" autoDeploy="true">

        <Valve className="org.apache.catalina.valves.RemoteIpValve"
        protocolHeader="X-Forwarded-Proto" />

        <Valve className="org.apache.catalina.valves.AccessLogValve"
directory="logs"
               prefix="localhost_access_log." suffix=".txt"
               pattern="%h %l %u %t &quot;%r&quot; %s %b"
resolveHosts="false"/>

      </Host>
    </Engine>
  </Service>
</Server>


-- 
View this message in context: http://old.nabble.com/Request-params-randomly-null-in-servlet%28s%29-tp32461421p32471737.html
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Re: Request params randomly null in servlet(s)

Posted by Pid <pi...@pidster.com>.
On 14/09/2011 16:38, Darius D. wrote:
> 

>> p
>>
> 
> Well the problem is that we already looked for that mode of failure, our
> servlet class has 0 instance variables... Basically it is a method like i
> pasted before, doing HttpSession session = request.getSession(); and if
> session is valid (it is!) immediately reading those params with String
> action = request.getParameter("type");
> 
> Request object is perfectly valid when those params are missing ( session,
> query etc are preserved, its just those params we are missing ). Error
> happens in bursts in a rate of ~25 / million requests.

What is your server.xml config?  (please remove comments, passwords etc
& post it inline, in the response)


p


Re: Request params randomly null in servlet(s)

Posted by "Darius D." <da...@gmail.com>.

Pid * wrote:
> 
> On 14/09/2011 11:55, Darius D. wrote:
> 
> They are in *that* thread.
> 
> It is possible to expose either request or response object outside of
> the scope of the thread, so a second request sees a modified version of
> the same object.
> 
> E.g.
> 
>  public class SomeServlet extends HttpServlet {
> 
>    private HttpServletRequest request;
> 
>    protected void doGet(HttpServletRequest rq, HttpServletResponse rs) {
> 
>      // this is a handy value, let's store it (FAIL!)
>      this.request = request;
> 
>      // do something...
>      process(this.request);
>      // finish...
> 
>    }
> 
>  }
> 
> 
> So a different thread entering the method causes the request object to
> be updated before the other thread has finished using it.  There are
> other, more subtle, ways to cause the same effect.
> 
> 
> p
> 

Well the problem is that we already looked for that mode of failure, our
servlet class has 0 instance variables... Basically it is a method like i
pasted before, doing HttpSession session = request.getSession(); and if
session is valid (it is!) immediately reading those params with String
action = request.getParameter("type");

Request object is perfectly valid when those params are missing ( session,
query etc are preserved, its just those params we are missing ). Error
happens in bursts in a rate of ~25 / million requests.







-- 
View this message in context: http://old.nabble.com/Request-params-randomly-null-in-servlet%28s%29-tp32461421p32464563.html
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Re: Request params randomly null in servlet(s)

Posted by Pid <pi...@pidster.com>.
On 14/09/2011 11:55, Darius D. wrote:
> 
> 
> 
> Pid * wrote:
>>
>> doProcess(req, res) is not a Servlet API method. What other method(s)
>> call it?
>>
>> Usually this type of thing occurs because the request (or response) is
>> being held as an instance field somewhere in a thread-unsafe way.
>>
>>
> 
> It is called from:
> 	public void doGet(HttpServletRequest request, HttpServletResponse response)
> throws ServletException, IOException {
> 		doProcess(request, response);
> 	}
> 
> and doPost(...) as well. 
> 
> I am not quite sure where and what could be holding the request, as this
> method is the called directly and request params are already NULL ?

They are in *that* thread.

It is possible to expose either request or response object outside of
the scope of the thread, so a second request sees a modified version of
the same object.

E.g.

 public class SomeServlet extends HttpServlet {

   private HttpServletRequest request;

   protected void doGet(HttpServletRequest rq, HttpServletResponse rs) {

     // this is a handy value, let's store it (FAIL!)
     this.request = request;

     // do something...
     process(this.request);
     // finish...

   }

 }


So a different thread entering the method causes the request object to
be updated before the other thread has finished using it.  There are
other, more subtle, ways to cause the same effect.


p





Re: Request params randomly null in servlet(s)

Posted by "Darius D." <da...@gmail.com>.


Pid * wrote:
> 
> doProcess(req, res) is not a Servlet API method. What other method(s)
> call it?
> 
> Usually this type of thing occurs because the request (or response) is
> being held as an instance field somewhere in a thread-unsafe way.
> 
> 

It is called from:
	public void doGet(HttpServletRequest request, HttpServletResponse response)
throws ServletException, IOException {
		doProcess(request, response);
	}

and doPost(...) as well. 

I am not quite sure where and what could be holding the request, as this
method is the called directly and request params are already NULL ?

-- 
View this message in context: http://old.nabble.com/Request-params-randomly-null-in-servlet%28s%29-tp32461421p32462485.html
Sent from the Tomcat - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Re: Request params randomly null in servlet(s)

Posted by Pid <pi...@pidster.com>.
On 14/09/2011 08:34, Darius D. wrote:
> 
> Hi,
> 
> we have a problem of request params beeing null in servlets where it
> shouldn't be ( post or get, in get we can even see that
> request.getQueryString() is fine, but params are null).
> 
> It is more pronounced when using dedicated thread executor, moving to
> threads provided by connector itself (with maxThreads="500" option using NIO
> ) seems to be lowering counts of errors. 
> 
> 
> Atm we are seeing 3 modes of failure in our tomcat setup ( nginx reverse
> proxy -> tomcat with NIO connector )
> 
> 
> 1)
> SEVERE: Error finishing response
> java.lang.NullPointerException
> 
> and/or
> 
> SEVERE: Error processing request
> java.lang.NullPointerException
> 
> in logs. ( could be some app problem, but still shady, as no stack trace is
> given, like if exception object is gone itself??? )
> 
> 2) Sometimes we get 502 (from nginx, that got upstream error) like Rakesh in
> other thread, from servlets that should be fine ( result of NPE in real
> strange places ).
> 
> 3) And most scary ones are the following:
> 
> 2011 09 13 14:18:20.568 WARN  Servlet  - error response: error=no action
> query: [type=groupsChangedAction&v=1315912033175] content type:null
> protocol: HTTP/1.0 length:-1 character encoding: null  GET
> 2011 09 13 14:18:20.937 WARN  Servlet  - error response: error=no action
> query: [type=groupsChangedAction&v=1315912699092] content type:null
> protocol: HTTP/1.0 length:-1 character encoding: null  GET
> 
> In tomcat access log they are shown as:
> 127.0.0.1 - - [13/Sep/2011:14:18:20 +0300] "GET
> /ourapp/servlet/Servlet?type=groupsChangedAction&v=1315912033175 HTTP/1.0"
> 200 15
> 127.0.0.1 - - [13/Sep/2011:14:18:20 +0300] "GET
> /ourapp/servlet/Servlet?type=groupsChangedAction&v=1315912699092 HTTP/1.0"
> 200 15
> 
> So as you can see, tomcat got that GET reqest with type and v params like it
> gets and processes thousands others.
> 
> Servlet code looks like:

doProcess(req, res) is not a Servlet API method. What other method(s)
call it?

> private void doProcess(HttpServletRequest request, HttpServletResponse
> response) throws IOException {
>                 HttpSession session = request.getSession();
>                 if (session != null) {
> 
>                         String action = request.getParameter("type");
>                         logger.debug("action: " + action);
>                        
>                         if (action == null) {
> 
>                                 printError(request, response,"error=no
> action");
> ....
> 
>         private void printError(HttpServletRequest request,
> HttpServletResponse response, String error) throws IOException {
>                 logger.warn("error response: " + error + " ip: "  +
> request.getRemoteAddr() + " query: [" + request.getQueryString() + "]" + "
> content type:" + request.getContentType() + " protocol: " +
> request.getProtocol() +  " length:" + request.getContentLength() + "
> character encoding: " + request.getCharacterEncoding() + "  " +
> request.getMethod());
>            
>                 response.setContentType("text/plain");
>                 PrintWriter out = response.getWriter();
>                 out.print(error);
>                 out.flush();
>                 out.close();
>         }
> 
> It happens several times in a day in bursts ( GC collecting something?).
> 
> 
> So really puzzling and random error, tomcat got proper request as shown in
> access logs (and even request.getQueryString() is valid :) ) , processed
> request from same user 5s ago, will process one more 5s later, but somehow
> request is NULL??? Now we handle it by retrying, but such random NULL is
> fatal for other servlets and services that throw NPEs and it seems that some
> tomcat code is affected too with (1).
>
> I'd grateful if some smart guys could look into this problem and willing to
> provide any other info.

Usually this type of thing occurs because the request (or response) is
being held as an instance field somewhere in a thread-unsafe way.


p

> Only connector running is:
>     <Connector port="8080"
> protocol="org.apache.coyote.http11.Http11NioProtocol"
>                connectionTimeout="20000"
>                enableLookups="false"
>                acceptCount="1000"
>                maxThreads="500"
>                maxPostSize="10485760"
>                 />
> 
> Also using 
> <Valve className="org.apache.catalina.valves.RemoteIpValve"
>         protocolHeader="X-Forwarded-Proto" />
> 
> 
> BR,
> 
> Darius. 
> 
> 
> 
>