Bug 51582 - NPE in SlowQueryReport
NPE in SlowQueryReport
Status: RESOLVED FIXED
Product: Tomcat Modules
Classification: Unclassified
Component: jdbc-pool
unspecified
PC Windows XP
: P2 major (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2011-07-29 08:07 UTC by Patric Rufflar
Modified: 2012-02-13 20:38 UTC (History)
1 user (show)



Attachments
test application to reproduce the bug (2.67 KB, application/octet-stream)
2012-01-27 09:22 UTC, Patric Rufflar
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Patric Rufflar 2011-07-29 08:07:18 UTC
java.lang.NullPointerException
	at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:768)
	at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.getQueryStats(SlowQueryReport.java:156)
	at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportFailedQuery(SlowQueryReport.java:85)
	at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx.reportFailedQuery(SlowQueryReportJmx.java:147)
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:236)
Comment 1 Patric Rufflar 2011-08-12 14:10:40 UTC
Another one:

java.lang.NullPointerException
	at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportFailedQuery(SlowQueryReport.java:86)
	at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx.reportFailedQuery(SlowQueryReportJmx.java:147)
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:236)
	at $Proxy7.executeQuery(Unknown Source)
Comment 2 Patric Rufflar 2011-08-12 14:15:43 UTC
Both exceptions seems to be caused due to race conditions (one thread is executing a statement, while another one is canceling it and possibly closing the ProxyConnection)
Comment 3 Patric Rufflar 2011-10-12 13:54:12 UTC
And also another one (most probably they all have the same cause).

java.lang.NullPointerException
 at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportSlowQuery(SlowQueryReport.j
ava:96)
 at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx.reportSlowQuery(SlowQueryRepor
tJmx.java:181)
 at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(Abstrac
tQueryReport.java:250)
 at $Proxy104.executeQuery(Unknown Source)


We're seeing this issue pretty often - is there an estimation when it is going to be fixed?
Comment 4 Filip Hanik 2011-10-27 19:47:47 UTC
(In reply to comment #0)
> java.lang.NullPointerException
>     at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:768)
>     at
> org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.getQueryStats(SlowQueryReport.java:156)
>     at
> org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportFailedQuery(SlowQueryReport.java:85)
>     at
> org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx.reportFailedQuery(SlowQueryReportJmx.java:147)
>     at
> org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:236)


This error implies the SQL is null. Do you have a full stack trace for this one?
Comment 5 Filip Hanik 2011-10-27 20:01:18 UTC
Patrick, in r1189978 this has been fixed. However, if you could post a full stack trace so I can figure out why there is no 'sql' string present, ie, I've missed a call that doesn't call
Comment 6 Patric Rufflar 2011-10-27 20:14:28 UTC
Hi Filip,

here is an extended stacktrace of comment #0, however I truncated the lower stack trace elements.

> (In reply to comment #0)

Note: As the name implies, CStatement.cancel() calls cancel() on the jdbc-pool's Proxy of the jdbc Statement.


java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:768)
        at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.getQueryStats(SlowQueryReport.jav
a:156)
        at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportFailedQuery(SlowQueryReport
.java:85)
        at org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx.reportFailedQuery(SlowQueryRep
ortJmx.java:147)
        at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(Abstrac
tQueryReport.java:236)
        at $Proxy96.cancel(Unknown Source)
        at my.product.jdbc.CStatement.cancel(CStatement.java:97)
		


BTW: What about the NPE in comment #1? It's unlikely that this exception related to a null sql query.
Comment 7 Filip Hanik 2011-12-02 01:04:49 UTC
(In reply to comment #6)

> 
> BTW: What about the NPE in comment #1? It's unlikely that this exception
> related to a null sql query.

hi Patric, I think it is very likely, the statement is

            QueryStats qs = this.getQueryStats(sql);
            qs.failure(delta, now);  <-- NPE here

if SQL is null, the qs variable is also null

Filip
Comment 8 Patric Rufflar 2012-01-26 18:04:42 UTC
Hi Filip,

I was able to debug the NPE situation (during a load test):
sql is suprisingly _not_ null, but SlowQueryReport.this.queries is:

    protected QueryStats getQueryStats(String sql) {
        ConcurrentHashMap<String,QueryStats> queries = SlowQueryReport.this.queries;
        if (queries==null) return null;    <-- null is returned here
...
Comment 9 Patric Rufflar 2012-01-27 09:22:10 UTC
Created attachment 28218 [details]
test application to reproduce the bug

This test application will do concurrently
- execute a statement
- cancel it
- close the connection

and repeat those steps infinitely.

On my machine, I am seeing the NPE every 5 seconds with this application.
(tested with oracle jdbc driver and database)
Please note, that you have to adjust user/pass/url/query.

The connection.close() is the source of the issue, which sets the query concurrent hash map to null.
Comment 10 Filip Hanik 2012-02-13 19:08:19 UTC
Fixed in r1243655
it was setting the query cache to null when the connection was returned to the pool instead of when the connection was actually closed
Comment 11 Patric Rufflar 2012-02-13 19:42:40 UTC
Thanks, Filip and welcome back.
Comment 12 Filip Hanik 2012-02-13 20:38:02 UTC
Fixed in r1243682 for the Tomcat 7 branch