NullPointerException during recovery of database with territory-based collation

• Key: DERBY-3302
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Critical
• Assignee: Mamta A. Satoor
• Reporter: Knut Anders Hatlen
• Component/s: Store
• Affects Version/s: 10.3.1.4, 10.3.2.1, 10.4.1.3
• Fix Version/s: 10.3.3.0, 10.4.1.3

Description

When logical undo is performed on a database with territory-based collation, you may get a NullPointerException in SQLChar.getCollationKey() because SQLChar.getLocaleFinder() returns null.

This bug was reported on derby-user: http://thread.gmane.org/gmane.comp.apache.db.derby.user/8253

Comments

[Knut Anders Hatlen]

Attaching a script which reproduces the failure. Follow these steps:

1. Start ij

2. Execute this command in ij:
        run 'npe.sql';

3. Terminate ij with Ctrl-C (don't terminate it with Ctrl-D or EXIT, as those commands will perform a clean shutdown)

4. Restart ij

5. Open a connection to the database with this command:
        connect 'jdbc:derby:colldb';

Then you'll get a NullPointerException with the following stack trace:

java.lang.NullPointerException
at org.apache.derby.iapi.types.SQLChar.getCollationKey(SQLChar.java:2516)
at org.apache.derby.iapi.types.WorkHorseForCollatorDatatypes.stringCompare(WorkHorseForCollatorDatatypes.java:88)
at org.apache.derby.iapi.types.CollatorSQLVarchar.stringCompare(CollatorSQLVarchar.java:159)
at org.apache.derby.iapi.types.SQLChar.compare(SQLChar.java:902)
at org.apache.derby.impl.store.access.btree.ControlRow.compareIndexRowToKey(ControlRow.java:1354)
at org.apache.derby.impl.store.access.btree.index.B2IUndo.findUndo(B2IUndo.java:221)
at org.apache.derby.impl.store.raw.data.LogicalPageOperation.findLogicalPage(LogicalPageOperation.java:358)
at org.apache.derby.impl.store.raw.data.LogicalPageOperation.generateUndo(LogicalPageOperation.java:164)
at org.apache.derby.impl.store.raw.log.FileLogger.undo(FileLogger.java:991)
at org.apache.derby.impl.store.raw.xact.Xact.abort(Xact.java:919)
at org.apache.derby.impl.store.raw.xact.XactFactory.rollbackAllTransactions(XactFactory.java:529)
at org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:1201)
at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1992)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:291)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:546)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:419)
at org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:1001)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1992)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:291)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:546)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:419)
at org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:753)
at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:201)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1992)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:291)
at org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1829)
at org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1695)
at org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1575)
at org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:994)
at org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:542)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:1957)
at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:255)
at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:54)
at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:68)
at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:211)
at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:119)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:154)
at org.apache.derby.impl.tools.ij.ij.dynamicConnection(ij.java:1238)
at org.apache.derby.impl.tools.ij.ij.ConnectStatement(ij.java:1088)
at org.apache.derby.impl.tools.ij.ij.ijStatement(ij.java:916)
at org.apache.derby.impl.tools.ij.utilMain.runScriptGuts(utilMain.java:328)
at org.apache.derby.impl.tools.ij.utilMain.go(utilMain.java:248)
at org.apache.derby.impl.tools.ij.Main.go(Main.java:215)
at org.apache.derby.impl.tools.ij.Main.mainCore(Main.java:181)
at org.apache.derby.impl.tools.ij.Main.main(Main.java:73)
at org.apache.derby.tools.ij.main(ij.java:59)
at org.apache.derby.iapi.tools.run.main(run.java:51)

[Mamta A. Satoor]

I tried following the instructions multiple times but can't get the npe to reproduce. This is what I tried
$ java -Dij.exceptionTrace=true org.apache.derby.tools.ij
ij version 10.4
ij> run 'npe.sql';
ij> connect 'jdbc:derby:colldb;create=true;territory=no_NO;collation=TERRITORY_BASED' as c1;
ij> create table t (x varchar(100) primary key);
0 rows inserted/updated/deleted
ij> autocommit off;
ij> insert into t values 'xxxx';
1 row inserted/updated/deleted
ij> connect 'jdbc:derby:colldb' as c2;
ij(C2)> insert into t values 'abab';
1 row inserted/updated/deleted
ij(C2)>
$ java -Dij.exceptionTrace=true org.apache.derby.tools.ij
ij version 10.4
ij> connect 'jdbc:derby:colldb';
ij> exit;

Notice that I Ctrl-C from the first session of ij. I am running this against the trunk.

[Kristian Waagan]

Hello Mamta,

I tried the repro as well, and I see varying results. Sometimes it works, sometimes it doesn't when I press CTRL-C using Cygwin on Windows XP. I don't know which mechanism is kicking in with CTRL-C, but the repro works every time if I kill ij with the task manager.
You can have a look at the timestamps of the log files to check if Derby was able to write something before exiting.


hth,

[Mamta A. Satoor]

Thanks, Kristian. crashing ij through task manager did the trick. I get the NPE now.

[Thomas Vatter]

This bug occured during the last week estimatedly every 32 hours, so I would ask for giving it a higher priority, as critical or blocker.

tom_

[Knut Anders Hatlen]

I agree. Raising the priority to 'Critical' since the bug makes it impossible to access the database.

[Mamta A. Satoor]

Commited a fix for this into trunk using revision 610846. I will work on merging this into 10.3 codeline and writing a test case. The tests ran fine on my Windows XP machine with Sun jdk1.4 The commit comments are as follows

DERBY-3302 The user was running into null pointer exception at the time of database recovery
because Derby was trying to get the Collator object through database context. But the
Collator object is already available in the territory sensitive character classes and we
do not have to go to database context to get it. I changed the code to use that collator
object rather than look into database context. The reason for null pointer exception was
that database context was not loaded yet during database recovery.

[Knut Anders Hatlen]

Thanks for fixing this so quickly, Mamta! I have verified that the repro runs without failure with the fix.

[Mamta A. Satoor]

Thanks for double-checking the fix, Knut. I am thinking of merging the fix into 10.3 tomorrow just to make sure that tests run fine on the tinderbox. All the tests ran fine on my machine.

[Mike Matrigali]

Could you comment on the SQLChar case, ie. the non collation recovery path. In that case is there something that
guarantees at recovery time that localeFinder won't be null and we will never enter the code for the database
context?:

   protected LocaleFinder getLocaleFinder()
   {
       // This is not very satisfactory, as it creates a dependency on
       // the DatabaseContext. It's the best I could do on short notice,
       // though. - Jeff
       if (localeFinder == null)
       {
           DatabaseContext dc = (DatabaseContext) ContextService.getContext(Dat
baseContext.CONTEXT_ID);
           if( dc != null)
               localeFinder = dc.getDatabase();
       }

       return localeFinder;
   }

[Mamta A. Satoor]

The majority of getLocaleFinder calls are from dead national character datatype code.

In addition, it is also called by existing code (ie the code before collation feature was added) for date, time and timestamp. I am not sure if that can run into problem during recovery.

One place that I find suspicious is the SQLChar.like(dvd, dvd) method line number 1767. This code is executed for non-national/non-collation sensitive character types ie for UCS_BASIC character types and the code looks as follows
  // Make sure we fail for both varchar an nvarchar
  // for multiple collation characters.
  SQLChar escapeSQLChar = (SQLChar) escape;
  int[] escapeIntArray = escapeSQLChar.getIntArray();
  if (escapeIntArray != null && (escapeIntArray.length != 1))
  {
  throw StandardException.newException(SQLState.LANG_INVALID_ESCAPE_CHARACTER,new String (escapeSQLChar.getCharArray()));
   }

So, it appears that we are trying to see if number of collation elements associated with escape character is more than 1 and if yes, then we throw exception. Seems like a code like above should be done for collation sensitive character types and not for UCS_BASIC character types. Interestingly, nothing like this is getting checked for national character datatypes. I entered jira entry DERBY-3315 for this.

[Mamta A. Satoor]

Committed a test case for this jira entry into trunk with revision 611295. the commit comments were as follows

Adding a test case for DERBY-3302. There are two sub-test case classes involved here, col_rec1.java and col_rec2.java

The purpose of col_rec1 test and col_rec2 test is to create a territory based database and create some objects with collation sensitive character types. Then, make the database crash so that during the recovery, store engine has to do collation related operations. Those collation related operations are going to require that we use correct Collator object. DERBY-3302 demonstrated a npe during this operation because Derby was relying on database context to get the correct Collator object. But database context is not available at this point in the recovery. With the fix for DERBY-3302, the Collator object will now be obtained from collation sensitive datatypes itself rather than looking at database context which is not available at this point in recovery.

col_rec1 class will do the steps of create a territory based database and create some objects with collation sensitive character types. Then, make the database crash. col_rec2 class will do the part of rebooting the crashed db which will require store to go through recovery.

[Mamta A. Satoor]

Merged changes from trunk revision(610846) into 10.3 codeline using revision 611297. Will work on merging the test case.

[Mamta A. Satoor]

Merged test changes from trunk revision(611295) into 10.3 codeline using revision 611298.

[Mamta A. Satoor]

I am finished with code changes and test changes for this jira entry. Would appreciate if Tom can give it a try. The changes are in trunk and 10.3 codeline.

[Thomas Vatter]

Which version do you recommend for deployment? Will 10.3.2.2 be an official release?

[Knut Anders Hatlen]

I'm not aware of any plans for making an official 10.3 release any time soon. The tentative schedule for the 10.4 release can be found here: http://wiki.apache.org/db-derby/DerbyTenFourRelease

If you want to build your own jar files for deployment, I think you're better off with 10.3. If you use the code in the development trunk, you'll probably run into upgrade issues when you switch to an official release later (databases created with trunk are generally not upgradeable).