Re: ScriptRunner.runScript() behavior mismatch when debugging

[Paul Krause]

My guess is that are having troubles with stale reads.  That is, your database client still thinks 'unitTest1' is in your table even after you deleted it.  Try experimenting with different transaction isolation levels and executors.

On Wednesday, October 10, 2012 4:45:02 PM UTC-4, Mike wrote:

Hello,

I apologize, but I wasn't able to boil the problem down to a workable test that could be reasonably posted.  Hopefully someone will be able to give me ideas of where to look based on the description I do have. 

I am using MyBatis 3.0.6 connecting to Sybase ASE 15.0.3.  

I have some unit tests that insert test data into the database via ScriptRunner.runScript() in order to execute the tests against.  In order to ensure the database is 'fresh' and ready for the newly inserted data, first I delete out my test data.  I have an SQL script that looks like:

delete from MyTable where ID = 'unitTest1';

insert into MyTable (ID) values ('unitTest1');  

This SQL is run with java code that looks like:

session = getSession();

conn = session.getConnection();

runner = new ScriptRunner(conn);

runner.setAutoCommit(true);

runner.setStopOnError(false);

try {

runner.runScript(Resources.getResourceAsReader("myscript.sql"));

conn.commit();

} catch (Exception ex) {

ex.printStackTrace();

}

When running the test, no error is displayed when executing the delete, the second line of the script throws an error about being unable to insert a duplicate key into MyTable.  

Where it gets really interesting is that if I trace through the code, and step over the "hasResults = statement.execute(command);" line in ScriptRunner.executeStatement(), then the delete actually happens.  If I don't drill down that far and I step over the "executeStatement(command.toString());" line in ScriptRunner.handleLine() (or any level higher), the delete doesn't actually occur in the database.  

Any suggestions on where to look for this particular ghost would be greatly appreciated.

--Mike

[Mike]

I put this on the back burner for a while, but now it's popped up on my list of things I need to nail down.

Because I'm having this problem connecting to Sybase, but not when running against SQL Server 2012.  I went out and upgraded my Sybase jdbc drivers to the latest version and am still having the problem.  What is most confusing to me is why this behaves the way it behaves differently during a debug session.  Consider the following code pulled from ScriptRunner.java:

  private StringBuffer handleLine(StringBuffer command, String line) throws SQLException, UnsupportedEncodingException {

    String trimmedLine = line.trim();

    if (lineIsComment(trimmedLine)) {

      println(trimmedLine);

    } else if (commandReadyToExecute(trimmedLine)) {

      command.append(line.substring(0, line.lastIndexOf(delimiter)));

      command.append(LINE_SEPARATOR);

      println(command);

      executeStatement(command.toString());

      command.setLength(0);

    } else if (trimmedLine.length() > 0) {

      command.append(line);

      command.append(LINE_SEPARATOR);

    }

    return command;

  }

  private void executeStatement(String command) throws SQLException, UnsupportedEncodingException {

    boolean hasResults = false;

    Statement statement = connection.createStatement();

    statement.setQueryTimeout(50000);

    if (stopOnError) {

      hasResults = statement.execute(command);

    } else {

      try {

        hasResults = statement.execute(command);

      } catch (SQLException e) {

        String message = "Error executing: " + command + ".  Cause: " + e;

        printlnError(message);

      }

    }

    printResults(statement, hasResults);

    try {

      statement.close();

    } catch (Exception e) {

      // Ignore to workaround a bug in some connection pools

    }

  }

If I step into the executeStatement method (first bolded line), when I reach the statement.execute() call (second bolded line), the delete happens.  I can verify this by externally looking at the rows in the table through isql.  If I instead step over the first executeStatement, I get no error message, but the row still exists in the database.  

I'm convinced this isn't a caching issue because I am verifying the existence of the row completely externally.  If it is a transaction issue, then the transaction is getting rolled back silently somewhere because there are no locks in the database.

One other hint I can find in here is triggers.  MyTable has a delete trigger which is cascading deletes to other tables.  If I remove this trigger, then the delete happens without a problem.  This may be a red herring though since the delete happens fine with isql, and of course most strangely fine if I trace right up to statement.execute.  

--Mike

[Guy Rouillier]

Perhaps you posted this to the wrong list? I don't see what this has to
do with MyBatis.

On 1/21/2013 4:35 PM, Mike wrote:
> I put this on the back burner for a while, but now it's popped up on my
> list of things I need to nail down.
>
> Because I'm having this problem connecting to Sybase, but not when
> running against SQL Server 2012. I went out and upgraded my Sybase jdbc
> drivers to the latest version and am still having the problem. What is
> most confusing to me is why this behaves the way it behaves differently
> during a debug session. Consider the following code pulled from
> ScriptRunner.java:
>
> private StringBuffer handleLine(StringBuffer command, String line)
> throws SQLException, UnsupportedEncodingException {
> String trimmedLine = line.trim();
> if (lineIsComment(trimmedLine)) {
> println(trimmedLine);
> } else if (commandReadyToExecute(trimmedLine)) {
> command.append(line.substring(0, line.lastIndexOf(delimiter)));
> command.append(LINE_SEPARATOR);
> println(command);

> * executeStatement(command.toString());*

> command.setLength(0);
> } else if (trimmedLine.length() > 0) {
> command.append(line);
> command.append(LINE_SEPARATOR);
> }
> return command;
> }
>
>
> private void executeStatement(String command) throws SQLException,
> UnsupportedEncodingException {
> boolean hasResults = false;
> Statement statement = connection.createStatement();
> statement.setQueryTimeout(50000);
> if (stopOnError) {
> hasResults = statement.execute(command);
> } else {
> try {

> * hasResults = statement.execute(command);*

> } catch (SQLException e) {
> String message = "Error executing: " + command + ". Cause: " + e;
> printlnError(message);
> }
> }
> printResults(statement, hasResults);
> try {
> statement.close();
> } catch (Exception e) {
> // Ignore to workaround a bug in some connection pools
> }
> }
>
>
> If I step into the executeStatement method (first bolded line), when I
> reach the statement.execute() call (second bolded line), the delete
> happens. I can verify this by externally looking at the rows in the
> table through isql. If I instead step over the first executeStatement,
> I get no error message, but the row still exists in the database.
>
> I'm convinced this isn't a caching issue because I am verifying the
> existence of the row completely externally. If it is a transaction
> issue, then the transaction is getting rolled back silently somewhere
> because there are no locks in the database.
>
>
> One other hint I can find in here is triggers. MyTable has a delete
> trigger which is cascading deletes to other tables. If I remove this
> trigger, then the delete happens without a problem. This may be a red
> herring though since the delete happens fine with isql, and of course
> most strangely fine if I trace right up to statement.execute.
>
> --Mike

--
Guy Rouillier

[Mike]

The methods I'm referencing getting different behavior tracing come directly from org.apache.ibatis.jdbc.ScriptRunner.

--Mike