Tuesday, June 3, 2014

JPA Annotations and Migrating from SQLServer to Derby in unit tests: A debugging case study

Problem: 

Our service layer has a series of integration tests that rely heavily on the data in the SQL Server development database. This was fraught with issues.

  • If the status of a targeted record changed, the tests would fail
  • If the test had an error, it would fail to cleanup and there would be "unitTestUsers" left in the db. 
  • If you were debugging, and didn't finish test execution, it wouldn't clean up the record
  • It was slow and required VPN access 

Solution: 

Move to Derby, which is an in-memory Java database.

Obviously we knew that we'd have to create all of the lookup tables, like the us_states table, and the roles table.

But we ran into numerous bugs which warrant a blog post.  I'm going to list them in order and how I solved them, but like an onion, resolving one layer lead to another and another.

Background: 

We are using JPA Annotations in a JAXB framework to manage the persistence. Derby (should) read these annotations and auto-generate the tables.

Roadblock: 

Missing tables:

We were getting a dozen missing tables and the tests would have the following errors:
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.4.2.v20130514-5956486): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLSyntaxErrorException: Table/View 'RC_ACTIVITY_LOG' does not exist.
Error Code: 20000

After exploring typos, case sensitivity, persistence.xml settings and configurations, there were two solutions that came out.  The short version is that there were 2 errors that were happening during the create table phase.

Discoveries: 

Turning on logging to "Fine" in the persistence.xml will output all of the SQL that is being run.
<property name="eclipselink.logging.level" value="FINE" />

Then, the log is very, very long (obviously), and was being cleared from the console.
So then I saved the output to a file.

This is easily done within IntelliJ in the Run/Debug Configurations window. There is a 3rd tab called "Logs" and a checkbox to indicate "Save console output to file:"

The following errors were discovered:
Internal Exception: java.sql.SQLSyntaxErrorException: Column name 'IDX' appears more than once in the CREATE TABLE statement.  
Error Code: 30000

With the corresponding SQL Statement:
CREATE TABLE job_category (occupation_id INTEGER GENERATED BY DEFAULT AS IDENTITY NOT NULL, major_group_id VARCHAR(255), profile_nbr INTEGER, idx INTEGER, idx INTEGER, PRIMARY KEY (occupation_id))

Notice the double "idx INTEGER?"

After much research, finally found that it was coming from our Annotations:
@OneToMany(cascade = CascadeType.ALL, mappedBy="profile", orphanRemoval = true)
@OrderColumn(name="idx") 

Couldn't figure out why it was doubling, but changing the name="idx" was reflected in the error (still doubled), and leaving it out resulted in the default name doubled. If you have an answer or link to why it doubles, and a better solution, I'd love to hear about it.

Ultimately, ended up copying the SQL statement from the logs, removed one of the idx references and recreated the table at the beginning of our tests.

Here is the code for that:
    private static void createTable(String sql)  throws Exception
    {
        Connection connection = getConnection();
        Statement stmt = connection.createStatement();
        stmt.executeUpdate(sql);
    }

    private static Connection getConnection() throws ClassNotFoundException, SQLException {
        String strConnectionURL = "jdbc:derby:memory:TestDB;create=true";
        Class.forName("org.apache.derby.jdbc.EmbeddedDriver");
        return DriverManager.getConnection(strConnectionURL);
    }

But then we ran into another problem error creating tables:

Internal Exception: java.sql.SQLSyntaxErrorException: Constraints 'SQL140602131233001' and 'SQL140602131233000' have the same set of columns, which is not allowed. 
Error Code: 30000

With its corresponding SQL
CREATE TABLE rc_activity_log (rc_activity_log_id INTEGER GENERATED BY DEFAULT AS IDENTITY NOT NULL UNIQUE, created_on_dt TIMESTAMP NOT NULL, NOTE VARCHAR(255), user_id INTEGER NOT NULL, profile_nbr INTEGER, PRIMARY KEY (rc_activity_log_id))

And the Annotations: 
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
@Column(name="rc_activity_log_id", unique=true, nullable=false)

Which means that because there is an @ID and unique=true, that it creates two identical constraints on the table, which causes it to fail. (Thanks https://java.net/jira/browse/GLASSFISH-3252)

Given that the code was working before the derby migration, and we didn't want to change any of that, We just manually created these tables as well.

Extra: 

One thing that was particularly helpful was being able to determine the actual tables that existed in memory. So from http://stackoverflow.com/questions/7411020/calling-derby-java-db-show-tables-from-jdbc we have:

public static void printDerbyTables() {
        //http://stackoverflow.com/questions/7411020/calling-derby-java-db-show-tables-from-jdbc
        try {
            Connection connection = getConnection();
            DatabaseMetaData dbmd = connection.getMetaData();
            ResultSet resultSet = dbmd.getTables(null, null, null, null);
            System.out.println("DERBY TABLES >>>>>>>>> ");
            while (resultSet.next()) {
                String strTableName = resultSet.getString("TABLE_NAME");
                System.out.println("TABLE_NAME is " + strTableName);
            }
            System.out.println("<<<<<<<<<<<<< END DERBY TABLES  ");
        } catch (ClassNotFoundException e) {
            e.printStackTrace();
        } catch (SQLException e) {
            e.printStackTrace();
        }
    }