iBatis for Java [READ ONLY]
  1. iBatis for Java [READ ONLY]
  2. IBATIS-152

NullPointer Exception thrown in GeneralStatement.executeQueryWithCallback when using Log4j

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.1.0
    • Fix Version/s: 2.1.5
    • Component/s: Core
    • Labels:
      None
    • Environment:
      Windows XP, Java 1.3

      Description

      Hi,

      I am trying to follow the supplied test for IBATIS-53 (Oracle ref cursors).

      I have found that running the supplied test (number 6) with log4j-1.2.9.jar on
      the classpath causes a NullPointerException.

      The stack trace and output is:

      DEBUG [main] - Created connection 3235124.
      DEBUG [main] -

      {conn-100000}

      Connection
      DEBUG [main] -

      {pstm-100001} PreparedStatement: { ? = call mis_extract.mgr_case_temp.FindCases }
      DEBUG [main] - {pstm-100001}

      Parameters: []
      DEBUG [main] -

      {pstm-100001}

      Types: []
      DEBUG [main] -

      {rset-100002}

      ResultSet
      DEBUG [main] - Returned connection 3235124 to pool.
      com.ibatis.common.jdbc.exception.NestedSQLException:
      — The error occurred in com/kinnect/mis/datamodel/sql/CaseToExtract.xml.
      — The error occurred while applying a parameter map.
      — Check the output.
      — Check the output parameters (retrieval of output parameters failed).
      — Cause: java.lang.NullPointerException
      Caused by: java.lang.NullPointerException
      at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:184)
      at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForObject(GeneralStatement.java:100)
      at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:561)
      at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:536)
      at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSessionImpl.java:97)
      at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.queryForObject(SqlMapClientImpl.java:69)
      at com.kinnect.mis.MISExtract.readCasesToExtract(MISExtract.java:233)
      at com.kinnect.mis.MISExtract.main(MISExtract.java:64)

      Caused by:
      java.lang.NullPointerException
      at java.lang.reflect.Method.invoke(Native Method)
      at com.ibatis.common.jdbc.logging.ResultSetLogProxy.invoke(ResultSetLogProxy.java:47)
      at $Proxy2.close(Unknown Source)
      at com.ibatis.sqlmap.engine.execution.SqlExecutor.closeResultSet(SqlExecutor.java:392)
      at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQueryProcedure(SqlExecutor.java:298)
      at com.ibatis.sqlmap.engine.mapping.statement.ProcedureStatement.sqlExecuteQuery(ProcedureStatement.java:34)
      at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryWithCallback(GeneralStatement.java:169)
      at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeQueryForObject(GeneralStatement.java:100)
      at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:561)
      at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:536)
      at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSessionImpl.java:97)
      at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.queryForObject(SqlMapClientImpl.java:69)
      at com.kinnect.mis.MISExtract.readCasesToExtract(MISExtract.java:233)
      at com.kinnect.mis.MISExtract.main(MISExtract.java:64)

      Is there a known problem with log4j with IBatis ?
      Is this a problem for RefCursors only ?

      1. PreparedStatementLogProxy_final.java
        3 kB
        Sven Boden
      2. StatementLogProxy_final.java
        3 kB
        Sven Boden
      3. RefCursor.zip
        11 kB
        David Winterbottom

        Activity

        Hide
        Clinton Begin added a comment -

        Fixed as described by Sven. Thanks again Sven!

        Show
        Clinton Begin added a comment - Fixed as described by Sven. Thanks again Sven!
        Hide
        Sven Boden added a comment -

        Full files instead of diff files. The fix solves IBATIS-152 and IBATIS-149 for sure and possibly IBATIS-116 (impossible to tell without a stack trace).

        The fix synchronizes the behaviour between iBatis with and without logging switched on.

        Regards,
        Sven Boden

        P.S. My CLA has been faxed to Apache

        Show
        Sven Boden added a comment - Full files instead of diff files. The fix solves IBATIS-152 and IBATIS-149 for sure and possibly IBATIS-116 (impossible to tell without a stack trace). The fix synchronizes the behaviour between iBatis with and without logging switched on. Regards, Sven Boden P.S. My CLA has been faxed to Apache
        Hide
        Sven Boden added a comment -

        I installed GNU diff on my PC. Attached to "diff -u" files to fix IBATIS-142, the patch may also possibly fix IBATIS-152 (pretty sure), IBATIS-149 and maybe IBATIS-116, all depending on the exact stack-traces generated by the latter bugs.

        The root cause for IBATIS-142 is that when that the proxy class PreparedStatementLogProxy (when logging is on) always wraps a ResultSet in a ResultSetLogProxy even when the original ResultSet is null. The effect of this is that later on when close() of the ResultSet is called ResultSetLogProxy tries to call the close method on the original "null" result with the NullPointerException as result.

        The solution is to only return a ResultSetLogProxy when the result is not empty, and null otherwise. This way the logging version of the functionality is in sync with the non-logging version.

        StatementLogProxy is included as it uses the same way of wrapping ResultSets and it may cause similar problems.

        If anyone is interested in receiving the full file for PreparedStatementLogProxy for testing purposes, let me know.

        Regards,
        Sven Boden
        list123@pandora.be

        Show
        Sven Boden added a comment - I installed GNU diff on my PC. Attached to "diff -u" files to fix IBATIS-142 , the patch may also possibly fix IBATIS-152 (pretty sure), IBATIS-149 and maybe IBATIS-116 , all depending on the exact stack-traces generated by the latter bugs. The root cause for IBATIS-142 is that when that the proxy class PreparedStatementLogProxy (when logging is on) always wraps a ResultSet in a ResultSetLogProxy even when the original ResultSet is null. The effect of this is that later on when close() of the ResultSet is called ResultSetLogProxy tries to call the close method on the original "null" result with the NullPointerException as result. The solution is to only return a ResultSetLogProxy when the result is not empty, and null otherwise. This way the logging version of the functionality is in sync with the non-logging version. StatementLogProxy is included as it uses the same way of wrapping ResultSets and it may cause similar problems. If anyone is interested in receiving the full file for PreparedStatementLogProxy for testing purposes, let me know. Regards, Sven Boden list123@pandora.be
        Hide
        Sven Boden added a comment -

        diff file

        Show
        Sven Boden added a comment - diff file
        Hide
        Sven Boden added a comment -

        Full file

        Show
        Sven Boden added a comment - Full file
        Hide
        Sven Boden added a comment -

        I've been too quick on the trigger... but I still do find it strange no CallableStatementLogProxy exists, but that's not the problem in this case. The problem is in com.ibatis.common.jdbc.logging.PreparedStatementLogProxy where in the invoke method for the "getResultSet" part a proxy is always returned (even when the result is empty).

        Later on in the code (com.ibatis.sqlmap.engine.execution.SqlExecutor method executeQueryProcedure()) a resultset is closed when it's not null, but since the result is always non-null in case of the proxies the close of the resultset fails with a NullPointerException (when the wrapped ResultSet is null).

        There are several solutions, the nicest solution seems to be to return null from PreparedStatementLogProxy for getResultSet() when the original ResultSet is empty.

        2 files attached, the changed PreparedLogProxyStatement.java and a .diff file (don't know whether the diff is ok, made under Windows).

        David, can you confirm the change fixes your problem?

        Regards,
        Sven Boden

        Show
        Sven Boden added a comment - I've been too quick on the trigger... but I still do find it strange no CallableStatementLogProxy exists, but that's not the problem in this case. The problem is in com.ibatis.common.jdbc.logging.PreparedStatementLogProxy where in the invoke method for the "getResultSet" part a proxy is always returned (even when the result is empty). Later on in the code (com.ibatis.sqlmap.engine.execution.SqlExecutor method executeQueryProcedure()) a resultset is closed when it's not null, but since the result is always non-null in case of the proxies the close of the resultset fails with a NullPointerException (when the wrapped ResultSet is null). There are several solutions, the nicest solution seems to be to return null from PreparedStatementLogProxy for getResultSet() when the original ResultSet is empty. 2 files attached, the changed PreparedLogProxyStatement.java and a .diff file (don't know whether the diff is ok, made under Windows). David, can you confirm the change fixes your problem? Regards, Sven Boden
        Hide
        Sven Boden added a comment -

        I did find the error, but have no firm solution yet... would like some input from the experts.

        The problem starts in com.ibatis.sqlmap.engine.execution.SqlExecutor method executeQueryProcedure(). The problem is that in there a CallableStatement (cs) is used in the following construct:

        CallableStatement cs = null;
        ResultSet rs = null;
        try {
        cs = conn.prepareCall(sql);
        ... SNIP SNIP
        cs.execute();
        rs = cs.getResultSet();
        ....

        Without debugging on this works ok. However with debugging on, the prepareCall() gets rerouted to com.ibatis.common.jdbc.logging.ConnectionLogProxy method invoke()... in which the "prepareCall" part always creates a PreparedStatement and never a callableStatement. My hunch is that callableStatement overrides some methods which slightly different functionality (in the Oracle driver).

        My proposed solution would be to make a CallableStatementLogProxy and in ConnectionLogProxy determine based on the required returntype of Method to make a proxy for PreparedStatement or CallableStatement. This would route the calls to the proper objects probably resulting in correct execution while debugging is on.

        Regards,
        Sven

        Show
        Sven Boden added a comment - I did find the error, but have no firm solution yet... would like some input from the experts. The problem starts in com.ibatis.sqlmap.engine.execution.SqlExecutor method executeQueryProcedure(). The problem is that in there a CallableStatement (cs) is used in the following construct: CallableStatement cs = null; ResultSet rs = null; try { cs = conn.prepareCall(sql); ... SNIP SNIP cs.execute(); rs = cs.getResultSet(); .... Without debugging on this works ok. However with debugging on, the prepareCall() gets rerouted to com.ibatis.common.jdbc.logging.ConnectionLogProxy method invoke()... in which the "prepareCall" part always creates a PreparedStatement and never a callableStatement. My hunch is that callableStatement overrides some methods which slightly different functionality (in the Oracle driver). My proposed solution would be to make a CallableStatementLogProxy and in ConnectionLogProxy determine based on the required returntype of Method to make a proxy for PreparedStatement or CallableStatement. This would route the calls to the proper objects probably resulting in correct execution while debugging is on. Regards, Sven
        Hide
        David Winterbottom added a comment -

        Hi Sven,

        I have tried the examples 5 and 6.

        I did not attempt example 4 because of the Comment by Ken Katsma [17/May/05 01:13 PM].
        Ken as this was commented as that example 4 was dynamic SQL and not refcursors.

        I have attached the code that I have used, and output.

        I am using an unchanged iBATIS_DBL-2.1.0.565.zip

        I have no problems using the refcursor with a oracle pl/sql function (5) and oracle pl/sql procedure (6)
        until I include the log4j jar file. Is there a problem with how I am configuring log4j. From the Developer guide
        all I required is the Jakarta Commons Logging and the log4j jar file.

        Show
        David Winterbottom added a comment - Hi Sven, I have tried the examples 5 and 6. I did not attempt example 4 because of the Comment by Ken Katsma [17/May/05 01:13 PM] . Ken as this was commented as that example 4 was dynamic SQL and not refcursors. I have attached the code that I have used, and output. I am using an unchanged iBATIS_DBL-2.1.0.565.zip I have no problems using the refcursor with a oracle pl/sql function (5) and oracle pl/sql procedure (6) until I include the log4j jar file. Is there a problem with how I am configuring log4j. From the Developer guide all I required is the Jakarta Commons Logging and the log4j jar file.
        Hide
        Sven Boden added a comment -

        I've been looking at the iBatis source code a bit...

        Can you try the examples in IBATIS-53 using an unchanged iBatis but with Type Handlers (using the last 3 showcases attached to IBATIS-53) and then report back. It's not necessary to change iBatis to support ref cursors (except for returning multiple resultsets, the IBATIS-53 is not really valid).

        Sven

        Show
        Sven Boden added a comment - I've been looking at the iBatis source code a bit... Can you try the examples in IBATIS-53 using an unchanged iBatis but with Type Handlers (using the last 3 showcases attached to IBATIS-53 ) and then report back. It's not necessary to change iBatis to support ref cursors (except for returning multiple resultsets, the IBATIS-53 is not really valid). Sven

          People

          • Assignee:
            Clinton Begin
            Reporter:
            David Winterbottom
          • Votes:
            2 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development