Bug #35666 NPE logging slow queries when useServerPrepStmts=true
Submitted: 29 Mar 2008 9:50 Modified: 7 Jul 2008 13:53
Reporter: Stephen Marquard Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:5.1.6 OS:Linux
Assigned to: CPU Architecture:Any

[29 Mar 2008 9:50] Stephen Marquard 
Description:
When useServerPrepStmts=true and slow query logging is enabled, the mysql connector throws an NPE when it encounters a slow query.

How to repeat:
To reproduce, use a connection string such as:

url@javax.sql.BaseDataSource=jdbc:mysql://localhost:3306/sakai?useUnicode=true&characterEncoding=UTF-8&useServerPrepStmts=true&slowQueryThresholdMillis=1&logSlowQueries=true&maxQuerySizeToLog=128000

Any query that takes > 1ms to execute generates an error such as the stack trace below, with the common factor being the NPE at ServerPreparedStatement.java:1396

java.sql.SQLException: java.lang.NullPointerException
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1055)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:864)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
        at org.sakaiproject.db.impl.BasicSqlService.dbRead(BasicSqlService.java:549)
        at org.sakaiproject.db.impl.BasicSqlService.dbRead(BasicSqlService.java:468)
        at org.sakaiproject.authz.impl.DbAuthzGroupService$DbStorage.isAllowed(DbAuthzGroupService.java:1505)
        at org.sakaiproject.authz.impl.BaseAuthzGroupService.isAllowed(BaseAuthzGroupService.java:832)
        at org.sakaiproject.authz.impl.SakaiSecurity.checkAuthzGroups(SakaiSecurity.java:289)
        at org.sakaiproject.authz.impl.SakaiSecurity.unlock(SakaiSecurity.java:256)
        at org.sakaiproject.authz.impl.SakaiSecurity.unlock(SakaiSecurity.java:223)
        at org.sakaiproject.authz.impl.SakaiSecurity.unlock(SakaiSecurity.java:215)
        at org.sakaiproject.authz.impl.SakaiSecurity.unlock(SakaiSecurity.java:201)
        at org.sakaiproject.site.impl.BaseSiteService.unlockCheck(BaseSiteService.java:165)
        at org.sakaiproject.site.impl.BaseSiteService.unlock(BaseSiteService.java:185)
        at org.sakaiproject.site.impl.BaseSiteService.getSiteVisit(BaseSiteService.java:701)
        at org.sakaiproject.site.cover.SiteService.getSiteVisit(SiteService.java:130)
        at org.sakaiproject.portal.util.PortalSiteHelper.getSiteVisit(PortalSiteHelper.java:559)
        at org.sakaiproject.portal.charon.handlers.SiteHandler.doSite(SiteHandler.java:189)
        at org.sakaiproject.portal.charon.handlers.SiteHandler.doGet(SiteHandler.java:114)
        at org.sakaiproject.portal.charon.SkinnableCharonPortal.doGet(SkinnableCharonPortal.java:891)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:592)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.NullPointerException
        at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1396)
        at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:838)
        ... 38 more
[31 Mar 2008 14:57] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/44686
[7 Jul 2008 13:53] Tony Bedford 
An entry has been added to the 5.1.6 Changelog:

When useServerPrepStmts=true and slow query logging is enabled, the connector throws a NullPointerException when it encounters a slow query.
[30 Jul 2008 14:53] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/50724