Hi Abhinav,
I spent some time digging into DERBY-6783.
This is a very interesting bug, and takes us right into
the heart of the trigger execution logic of the Derby engine.
I don't yet know what the answer is, but I made some good progress.
I'm attaching a fairly large patch to DERBY-6783, with all
of my debugging statements included, so you can run it in your
sandbox and reproduce the behaviors I'm seeing.
Here's what to do:
1) First, clean your sandbox, by doing:
- cd trunk
- svn revert -R .
- svn stat
This should show that your sandbox is clean.
2) Then download and apply the patch that I attached to DERBY-6783,
and run 'svn stat' again. You should see these files modified:
M java\engine\org\apache\derby\impl\jdbc\EmbedResultSet.java
M
java\engine\org\apache\derby\impl\sql\execute\GenericTriggerExecutor.java
M
java\engine\org\apache\derby\impl\sql\execute\InternalTriggerExecutionContext.java
M java\engine\org\apache\derby\impl\sql\execute\RowTriggerExecutor.java
M java\engine\org\apache\derby\impl\sql\execute\TriggerEventActivator.java
M java\engine\org\apache\derby\impl\sql\execute\UpdateResultSet.java
M
java\testing\org\apache\derbyTesting\functionTests\tests\lang\TriggerWhenClauseTest.java
In my patch, I changed the trigger test slightly, to give the
trigger and the table different names to make them stand out more
easily in the output. So the trigger is now called TRIGGER6783
in my patch.
3) Then clean and rebuild your sandbox:
- ant clobber
- ant cleanjars
- ant all
- ant buildjars
4) Then run the test. It will generate a LOT of output, so we're
redirecting the output to a file:
- ant
-Dderby.junit.testclass=org.apache.derbyTesting.functionTests.tests.lang.TriggerWhenClauseTest
junit-clean junit-single >test.out
2>&1
5) Then bring up 'test.out' in your editor, and search for TRIGGER6783
You should see the following output:
[junit] TRIGGER: TRIGGER6783
[junit] UpdateResultSet constructor, deferred = true
[junit] fireBeforeTriggers()
[junit] TriggerEventActivator.notifyEvent: no executors for event 2
[junit] fireafterTriggers()
[junit] fireafterTriggers() - deferred
[junit] fireafterTriggers() - have triggerActivator
[junit] TriggerEventActivator.notifyEvent: FOUND executor for event 5
[junit] TriggerEventActivator.notifyEvent: firing executor trigger
[junit] RowTriggerExecutor.fireTrigger
[junit] GenericTriggerExecutor.getWhenClause
[junit] GenericTriggerExecutor.getWhenClause: clause=SPSDescriptor:
[junit] name:
TEST_DBO.TRIGGERWHEN_16a704f9-014d-989c-3b9d-0000412c11e9_af36c4f3-014d-989c-3b9d-0000412c11e9
[junit] uuid: 3923c4fb-014d-989c-3b9d-0000412c11e9
[junit] text: VALUES CAST
(org.apache.derby.iapi.db.Factory::getTriggerExecutionContext().getNewRow().getObject(1)
AS CHAR(1)) ='d'
[junit] valid: TRUE
[junit] preparedStatement: GSPS 1310148688 activationClassName=null
className=org.apache.derby.exe.ac8cbe04f1x014dx989cx3b9dx0000412c11e90
[junit]
[junit] GenericTriggerExecutor.executeWhenClauseAndAction:
descriptor=SPSDescriptor:
[junit] name:
TEST_DBO.TRIGGERWHEN_16a704f9-014d-989c-3b9d-0000412c11e9_af36c4f3-014d-989c-3b9d-0000412c11e9
[junit] uuid: 3923c4fb-014d-989c-3b9d-0000412c11e9
[junit] text: VALUES CAST
(org.apache.derby.iapi.db.Factory::getTriggerExecutionContext().getNewRow().getObject(1)
AS CHAR(1)) ='d'
[junit] valid: TRUE
[junit] preparedStatement: GSPS 1310148688 activationClassName=null
className=org.apache.derby.exe.ac8cbe04f1x014dx989cx3b9dx0000412c11e90
[junit]
[junit] GenericTriggerExecutor.executeSPS
[junit] GenericTriggerExecutor: This is a WHEN clause
[junit] InternalTriggerExecutionContext.getNewRow:
rs=org.apache.derby.impl.jdbc.EmbedResultSet@4b969e3c,rs.next() returned true
[junit] EmbedResultSet.GetObject(1): columnType=4
[junit] EmbedResultSet.GetObject(1): return object 1
[junit] GeneriCTriggerExecutor: whenClauseWasTrue=false
[junit] GenericTriggerExecutor: done with execution
You can see from this output that event 5 is being processed, which as
we see in TriggerEvent.java is:
public class TriggerEvent
{
static final int BEFORE_INSERT = 0;
static final int BEFORE_DELETE = 1;
static final int BEFORE_UPDATE = 2;
static final int LAST_BEFORE_EVENT = BEFORE_UPDATE;
static final int AFTER_INSERT = 3;
static final int AFTER_DELETE = 4;
static final int AFTER_UPDATE = 5;
So we're firing our trigger on the right event.
And the "WHEN" clause looks reasonable; it is comparing the value in column 1
of the new row to the literal value 'd':
[junit] text: VALUES CAST (org.apache.derby.iapi.db.Factory::
getTriggerExecutionContext().getNewRow().getObject(1) AS CHAR(1)) ='d'
And we successfully get the new row and we successfully get the column's value.
Here's where it gets pretty interesting. The column's columnType is 4, which
as we can see here:
http://docs.oracle.com/javase/6/docs/api/constant-values.html#java.sql.Types.INTEGER
is the SQL type INTEGER.
And the value of the column is, converted to a string, 1:
[junit] EmbedResultSet.GetObject(1): return object 1
Now, this makes sense, in a way, because column 1 in the table is "ID INTEGER":
s.execute("CREATE TABLE tabDerby6783(id INTEGER, result VARCHAR(10), status
CHAR(1))");
And the ID value of our row is 1:
s.execute("insert into tabDerby6783 values (1, null, 'a')");
But since the trigger is referencing the STATUS column, the trigger should
have been compiled to "getNewRow().getObject(3) AS CHAR(1)".
So the mystery, I think, is how the trigger got confused about which column
was the STATUS column, and encoded the wrong column number into
the triggerInfo at compilation time.
I'll try to find some time to look into the compilation aspects of the
trigger soon, but I've run out of time for today so this is as far as
I got.
Let me know if you're able to reproduce the behaviors I'm seeing!
thanks,
bryan
