Derby
  1. Derby
  2. DERBY-4435

Emptying index fails with NPE doing replacement import of empty file

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.3.3.0, 10.4.2.0, 10.5.3.0, 10.6.1.0
    • Fix Version/s: 10.4.2.1, 10.5.3.1, 10.6.1.0
    • Component/s: Store
    • Labels:
      None
    • Environment:
      Doing replacement import resulting in an empty table, where the table has at least one index.
    • Issue & fix info:
      Repro attached
    • Bug behavior facts:
      Crash, Regression, Seen in production

      Description

      When importing data from an empty file, with the replacement option enabled (non-zero last argument in the import procedure call), Derby fails with a NullPointerException when emptying the index(es) .

      Stack trace, insane build:
      java.sql.SQLException: Import error on line 1 of file [snip]: Java exception: ': java.lang.NullPointerException'.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95)
      ...
      Caused by: java.lang.NullPointerException
      at org.apache.derby.impl.sql.execute.InsertResultSet.emptyIndexes(InsertResultSet.java:2348)
      at org.apache.derby.impl.sql.execute.InsertResultSet.updateAllIndexes(InsertResultSet.java:1820)
      at org.apache.derby.impl.sql.execute.InsertResultSet.bulkInsertCore(InsertResultSet.java:1356)
      at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:444)
      at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:436)
      at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:317)
      at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)
      ... 44 more

      Stack trace, sane build:
      java.sql.SQLException: The exception 'java.sql.SQLException: An internal error was identified by RawStore module.' was thrown while evaluating an expression.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95)
      ...
      Caused by: ERROR 40XT0: An internal error was identified by RawStore module.
      at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:276)
      at org.apache.derby.impl.store.raw.xact.Xact.abort(Xact.java:917)
      at org.apache.derby.impl.store.access.RAMTransaction.abort(RAMTransaction.java:1985)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(GenericLanguageConnectionContext.java:1496)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.userRollback(GenericLanguageConnectionContext.java:1404)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.rollback(TransactionResourceImpl.java:244)
      at org.apache.derby.impl.jdbc.EmbedConnection.rollback(EmbedConnection.java:1764)
      ... 40 more

      A quick investigation suggests DERBY-2537 added the code that fails.

      Problem reported by a user on the Derby user list, see http://thread.gmane.org/gmane.comp.apache.db.derby.user/11764

      1. Derby4435Repro.java
        3 kB
        Kristian Waagan

        Activity

        Hide
        Kristian Waagan added a comment -

        Attached repro (Derby4435Repro.java).

        Show
        Kristian Waagan added a comment - Attached repro (Derby4435Repro.java).
        Hide
        Kristian Waagan added a comment -

        Marking as regression.
        The results I see with the repro are not consistent with what the user reported. The repro triggers the bug in all the 10.3.X versions I have tried. 10.2 passes.

        Show
        Kristian Waagan added a comment - Marking as regression. The results I see with the repro are not consistent with what the user reported. The repro triggers the bug in all the 10.3.X versions I have tried. 10.2 passes.
        Hide
        Mamta A. Satoor added a comment -

        I thought I would post the script to repro the problem in ij (make sure you have an empty empty_file.dat in the directory where ij is getting run)

        java -Dij.exceptionTrace=true org.apache.derby.tools.ij
        connect 'jdbc:derby:c:/dellater/db;create=true';
        drop table IMPORT_TABLE;
        create table IMPORT_TABLE (text varchar(20));
        create index idx on IMPORT_TABLE(text);
        call SYSCS_UTIL.SYSCS_IMPORT_TABLE ('APP','IMPORT_TABLE','empty_file.dat','|','``',null,1);

        Show
        Mamta A. Satoor added a comment - I thought I would post the script to repro the problem in ij (make sure you have an empty empty_file.dat in the directory where ij is getting run) java -Dij.exceptionTrace=true org.apache.derby.tools.ij connect 'jdbc:derby:c:/dellater/db;create=true'; drop table IMPORT_TABLE; create table IMPORT_TABLE (text varchar(20)); create index idx on IMPORT_TABLE(text); call SYSCS_UTIL.SYSCS_IMPORT_TABLE ('APP','IMPORT_TABLE','empty_file.dat','|','``',null,1);
        Hide
        Mamta A. Satoor added a comment -

        I will debug this more but I am not able to see what exactly is casuing a npe. When I debug using eclipse, it is interesting that right when I get to
        Thread [main] (Suspended (breakpoint at line 2348 in InsertResultSet))
        InsertResultSet.emptyIndexes(long, InsertConstantAction, TableDescriptor, DataDictionary, ExecRow) line: 2347
        InsertResultSet.updateAllIndexes(long, InsertConstantAction, TableDescriptor, DataDictionary, ExecRow) line: 1820
        InsertResultSet.bulkInsertCore(LanguageConnectionContext, long) line: 1356
        InsertResultSet.open() line: 444
        GenericPreparedStatement.executeStmt(Activation, boolean, long) line: 436
        GenericPreparedStatement.execute(Activation, long) line: 317
        EmbedPreparedStatement30(EmbedStatement).executeStatement(Activation, boolean, boolean) line: 1235
        EmbedPreparedStatement30(EmbedPreparedStatement).executeStatement(Activation, boolean, boolean) line: 1675
        EmbedPreparedStatement30(EmbedPreparedStatement).executeUpdate() line: 302
        Import.performImport(Connection, String, String, String, String, String, String, String, String, short, boolean) line: 272
        Import.importTable(Connection, String, String, String, String, String, String, short, boolean) line: 124
        SystemProcedures.SYSCS_IMPORT_TABLE(String, String, String, String, String, String, short) line: 1464
        acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available
        NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
        NativeMethodAccessorImpl.invoke(Object, Object[]) line: 79
        DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43
        Method.invoke(Object, Object...) line: 618
        ReflectMethod.invoke(Object) line: 46
        CallStatementResultSet.open() line: 76
        GenericPreparedStatement.executeStmt(Activation, boolean, long) line: 436
        GenericPreparedStatement.execute(Activation, long) line: 317
        EmbedStatement.executeStatement(Activation, boolean, boolean) line: 1235
        EmbedStatement.execute(String, boolean, boolean, int, int[], String[]) line: 625
        EmbedStatement.execute(String) line: 555
        ij.executeImmediate(String) line: 329
        utilMain.doCatch(String) line: 521
        utilMain.runScriptGuts() line: 363
        utilMain.go(LocalizedInput[], LocalizedOutput) line: 261
        Main.go(LocalizedInput, LocalizedOutput) line: 229
        Main.mainCore(String[], Main) line: 184
        Main.main(String[]) line: 75
        ij.main(String[]) line: 59
        I simply get a NPE without being able to get into the method to see what is the source of NPE. Maybe something is wrong with my setup of Eclipse but I was wondering if anyone has little time to see if there are able to see where exactly npe is generated. I have tried with both sane and insane builds.

        Show
        Mamta A. Satoor added a comment - I will debug this more but I am not able to see what exactly is casuing a npe. When I debug using eclipse, it is interesting that right when I get to Thread [main] (Suspended (breakpoint at line 2348 in InsertResultSet)) InsertResultSet.emptyIndexes(long, InsertConstantAction, TableDescriptor, DataDictionary, ExecRow) line: 2347 InsertResultSet.updateAllIndexes(long, InsertConstantAction, TableDescriptor, DataDictionary, ExecRow) line: 1820 InsertResultSet.bulkInsertCore(LanguageConnectionContext, long) line: 1356 InsertResultSet.open() line: 444 GenericPreparedStatement.executeStmt(Activation, boolean, long) line: 436 GenericPreparedStatement.execute(Activation, long) line: 317 EmbedPreparedStatement30(EmbedStatement).executeStatement(Activation, boolean, boolean) line: 1235 EmbedPreparedStatement30(EmbedPreparedStatement).executeStatement(Activation, boolean, boolean) line: 1675 EmbedPreparedStatement30(EmbedPreparedStatement).executeUpdate() line: 302 Import.performImport(Connection, String, String, String, String, String, String, String, String, short, boolean) line: 272 Import.importTable(Connection, String, String, String, String, String, String, short, boolean) line: 124 SystemProcedures.SYSCS_IMPORT_TABLE(String, String, String, String, String, String, short) line: 1464 acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 79 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43 Method.invoke(Object, Object...) line: 618 ReflectMethod.invoke(Object) line: 46 CallStatementResultSet.open() line: 76 GenericPreparedStatement.executeStmt(Activation, boolean, long) line: 436 GenericPreparedStatement.execute(Activation, long) line: 317 EmbedStatement.executeStatement(Activation, boolean, boolean) line: 1235 EmbedStatement.execute(String, boolean, boolean, int, int[], String[]) line: 625 EmbedStatement.execute(String) line: 555 ij.executeImmediate(String) line: 329 utilMain.doCatch(String) line: 521 utilMain.runScriptGuts() line: 363 utilMain.go(LocalizedInput[], LocalizedOutput) line: 261 Main.go(LocalizedInput, LocalizedOutput) line: 229 Main.mainCore(String[], Main) line: 184 Main.main(String[]) line: 75 ij.main(String[]) line: 59 I simply get a NPE without being able to get into the method to see what is the source of NPE. Maybe something is wrong with my setup of Eclipse but I was wondering if anyone has little time to see if there are able to see where exactly npe is generated. I have tried with both sane and insane builds.
        Hide
        Myrna van Lunteren added a comment -

        I believe you're getting into a generated class there, at least there's this line:
        "acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available"
        , so the eclipse's debugger couldn't show that to you.

        There's a wiki on analyzing errors from a generated class: http://wiki.apache.org/db-derby/DumpClassFile

        Show
        Myrna van Lunteren added a comment - I believe you're getting into a generated class there, at least there's this line: "acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available" , so the eclipse's debugger couldn't show that to you. There's a wiki on analyzing errors from a generated class: http://wiki.apache.org/db-derby/DumpClassFile
        Hide
        Mamta A. Satoor added a comment -

        Myrna, where are you seeing this "acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available"? Both in and outside of eclipse, I do not see it in my stack trace.

        Show
        Mamta A. Satoor added a comment - Myrna, where are you seeing this "acf81e0010x0124xc63fxedebx00000017dda80.g0() line: not available"? Both in and outside of eclipse, I do not see it in my stack trace.
        Hide
        Mamta A. Satoor added a comment -

        I do see "acf81e0010x0124xc63fxedebx00000017dda80.g0()" line in my stack trace.

        I will look through the generated class further but still puzzled a little about why I do not get more info about where the npe is coming from.

        Show
        Mamta A. Satoor added a comment - I do see "acf81e0010x0124xc63fxedebx00000017dda80.g0()" line in my stack trace. I will look through the generated class further but still puzzled a little about why I do not get more info about where the npe is coming from.
        Hide
        Mamta A. Satoor added a comment -

        I tried running ij with -Dderby.debug.true=DumpClassFile so generated class files can be dumped but I guess it can't do it because the statement results into NPE and hence no class can be dumped. I will try it with sane build.

        Show
        Mamta A. Satoor added a comment - I tried running ij with -Dderby.debug.true=DumpClassFile so generated class files can be dumped but I guess it can't do it because the statement results into NPE and hence no class can be dumped. I will try it with sane build.
        Hide
        Mamta A. Satoor added a comment -

        With sane build, since there is no NPE, I was able to get couple class files. I will look into those to see if there is anything wrong in there which could cause NPE,

        Show
        Mamta A. Satoor added a comment - With sane build, since there is no NPE, I was able to get couple class files. I will look into those to see if there is anything wrong in there which could cause NPE,
        Hide
        Kristian Waagan added a comment -

        From the mail thread referenced above (sorry, forgot to add this when I logged the Jira):
        "A quick (and not that thorough) debugging session seems to have led me
        to the problem, which is related to the addition of collation support.

        The NPE happens here (from line 2348) in InsertResultSet.emptyIndexes:
        newIndexCongloms[index] =
        tc.createAndLoadConglomerate(
        "BTREE",
        indexRows[index].getRowArray(),
        null, //default column sort order
        collation[index],
        properties,
        TransactionController.IS_DEFAULT,
        rowSources[index],
        (long[]) null);

        The problem is that the variable 'collation' hasn't been initialized and
        is null.
        Adding "int[][] collation = new int[numIndexes][];" to the
        top of the method makes the repro pass, but I haven't studied the code
        or run the regression tests.
        "

        Can you confirm that you see the same issue?
        I'm not familiar with the code. When I had a look at it, it wasn't immediately clear to me if using a local collation array in the method emptyIndexes is correct, or if the instance variable have to be initialized / updated.
        Since the collation array is initialized in setupAllSorts from changedRow, it will be null when used in emptyIndexes (assuming InsertResultSet-instances aren't reused). As we don't have any rows to insert in emptyIndexes, maybe having an array with nulls is sufficient?

        Show
        Kristian Waagan added a comment - From the mail thread referenced above (sorry, forgot to add this when I logged the Jira): "A quick (and not that thorough) debugging session seems to have led me to the problem, which is related to the addition of collation support. The NPE happens here (from line 2348) in InsertResultSet.emptyIndexes: newIndexCongloms [index] = tc.createAndLoadConglomerate( "BTREE", indexRows [index] .getRowArray(), null, //default column sort order collation [index] , properties, TransactionController.IS_DEFAULT, rowSources [index] , (long[]) null); The problem is that the variable 'collation' hasn't been initialized and is null. Adding "int[][] collation = new int [numIndexes] [];" to the top of the method makes the repro pass, but I haven't studied the code or run the regression tests. " Can you confirm that you see the same issue? I'm not familiar with the code. When I had a look at it, it wasn't immediately clear to me if using a local collation array in the method emptyIndexes is correct, or if the instance variable have to be initialized / updated. Since the collation array is initialized in setupAllSorts from changedRow, it will be null when used in emptyIndexes (assuming InsertResultSet-instances aren't reused). As we don't have any rows to insert in emptyIndexes, maybe having an array with nulls is sufficient?
        Hide
        Mamta A. Satoor added a comment -

        Thanks for the additional info, Kristian. I will look into collation array being null.

        Show
        Mamta A. Satoor added a comment - Thanks for the additional info, Kristian. I will look into collation array being null.
        Hide
        Mamta A. Satoor added a comment -

        Committed fix into trunk with revision 834725. The fix involves initializing the collation arrary correctly.

        Show
        Mamta A. Satoor added a comment - Committed fix into trunk with revision 834725. The fix involves initializing the collation arrary correctly.
        Hide
        Kristian Waagan added a comment -

        Thanks, Mamta.

        I have tested the change, and no longer see the bug.
        I have also started tests on the 10.5 branch. Do you see any reasons why the fix shouldn't be back-ported to 10.5?

        The reason why I want to back-port is because of the user that reported the problem. If they decide to build their own version, using the 10.5 branch is a lot safer than using trunk.
        I can do the back-port if you don't plan to do it (let me know your plans).

        Show
        Kristian Waagan added a comment - Thanks, Mamta. I have tested the change, and no longer see the bug. I have also started tests on the 10.5 branch. Do you see any reasons why the fix shouldn't be back-ported to 10.5? The reason why I want to back-port is because of the user that reported the problem. If they decide to build their own version, using the 10.5 branch is a lot safer than using trunk. I can do the back-port if you don't plan to do it (let me know your plans).
        Hide
        Mamta A. Satoor added a comment -

        Kristian, first of all, thanks for verifying my changes.

        I was planning to backport to 10.5 next week after the changes have sat successsfully on trunk for a week or so. But if the tests run fine on your backport to 10.5 codeline, please feel free to commit them.

        Show
        Mamta A. Satoor added a comment - Kristian, first of all, thanks for verifying my changes. I was planning to backport to 10.5 next week after the changes have sat successsfully on trunk for a week or so. But if the tests run fine on your backport to 10.5 codeline, please feel free to commit them.
        Hide
        Kristian Waagan added a comment -

        Back-ported the fix to the 10.5 and 10.4 branches with revisions 880671 and 880768.
        All regression tests passed on 10.5, I got one error with 10.4: derbyall/encryptionAll/encryptionAll.fail:store/aes.sql
        I believe the error is unrelated to the back-port.

        Resolving issue, will keep it open a little while in case of complications.

        Show
        Kristian Waagan added a comment - Back-ported the fix to the 10.5 and 10.4 branches with revisions 880671 and 880768. All regression tests passed on 10.5, I got one error with 10.4: derbyall/encryptionAll/encryptionAll.fail:store/aes.sql I believe the error is unrelated to the back-port. Resolving issue, will keep it open a little while in case of complications.
        Hide
        Brett Wooldridge added a comment -

        I am encounter what appears to be this same issue.

        I have a zero-byte import file, a collation of TERRITORY_BASED:PRIMARY, and the following call dies with an NPE:

        CALL SYSCS_UTIL.SYSCS_IMPORT_DATA ('APP', 'TOOL_DETAILS', 'ID,EXECUTION_ID,IP_ADDRESS,NETWORK,START_TIME,END_TIME,ERROR,GRID_DATA,DETAILS', null, 'tmp/TOOL_DETAILS.del', ',' ,'"', 'UTF-8', 1);

        ERROR XIE0R: DERBY SQL error: SQLCODE: -1, SQLSTATE: XIE0R, SQLERRMC: 1tmp/TOOL_DETAILS.delJava exception: ': java.lang.NullPointerException'.XIE0R.SXJ001:java.lang.NullPointerExceptionXJ001.U
        ERROR XJ001: DERBY SQL error: SQLCODE: 0, SQLSTATE: XJ001, SQLERRMC: java.lang.NullPointerExceptionXJ001.U

        Show
        Brett Wooldridge added a comment - I am encounter what appears to be this same issue. I have a zero-byte import file, a collation of TERRITORY_BASED:PRIMARY, and the following call dies with an NPE: CALL SYSCS_UTIL.SYSCS_IMPORT_DATA ('APP', 'TOOL_DETAILS', 'ID,EXECUTION_ID,IP_ADDRESS,NETWORK,START_TIME,END_TIME,ERROR,GRID_DATA,DETAILS', null, 'tmp/TOOL_DETAILS.del', ',' ,'"', 'UTF-8', 1); ERROR XIE0R: DERBY SQL error: SQLCODE: -1, SQLSTATE: XIE0R, SQLERRMC: 1tmp/TOOL_DETAILS.delJava exception: ': java.lang.NullPointerException'.XIE0R.SXJ001:java.lang.NullPointerExceptionXJ001.U ERROR XJ001: DERBY SQL error: SQLCODE: 0, SQLSTATE: XJ001, SQLERRMC: java.lang.NullPointerExceptionXJ001.U
        Hide
        Brett Wooldridge added a comment -

        Note, if the 'replace' parameter is changed from 1 to 0, the statement does not fail.

        Show
        Brett Wooldridge added a comment - Note, if the 'replace' parameter is changed from 1 to 0, the statement does not fail.
        Hide
        Knut Anders Hatlen added a comment -

        Hi Brett,

        Do you have the full stack trace for the NPE? The table definition (including constraints and indexes) may also be useful when trying to reproduce the bug.

        Show
        Knut Anders Hatlen added a comment - Hi Brett, Do you have the full stack trace for the NPE? The table definition (including constraints and indexes) may also be useful when trying to reproduce the bug.
        Hide
        Knut Anders Hatlen added a comment -

        Closing this issue again since the problem originally reported was fixed and verified by the reporter. Brett, if you have more information about the failure you saw, please file a new bug report and post the info there.

        Show
        Knut Anders Hatlen added a comment - Closing this issue again since the problem originally reported was fixed and verified by the reporter. Brett, if you have more information about the failure you saw, please file a new bug report and post the info there.

          People

          • Assignee:
            Mamta A. Satoor
            Reporter:
            Kristian Waagan
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development