FieldReferenceLinker._lastAccessedFieldReference bleed-through

[Alec Wysoker]

Hi Max,

I mentioned previously that sometimes Squeryl produced SQL queries that were not valid, but I couldn't come up with a good reproduction procedure.  I still don't have a great reproduction procedure independent of my code base, but after much debugging I have gained some understanding of what is going on.  There is an attribute FieldReferenceLinker._lastAccessedFieldReference.  It looks like this is supposed to be used, then cleared when it is done being used.  It doesn't appear to be getting cleared in all cases.  What I see is that sometimes a value stored in the attribute from a previous operation bleeds through into the next query, and messes up the query.  

I have seen this when using relations like this:

 lazy val notificationStatuses = MySchema.workflowToNotificationStatus.left(this)

I have worked around this problem by doing this:

 lazy val notificationStatuses = {
   MySchema.clearFieldReferenceLinker
   MySchema.workflowToNotificationStatus.left(this)
 }

Where MySchema.clearFieldReferenceLinker is

 def clearFieldReferenceLinker = (new YieldInspection).cleanUp

I haven't wrapped my head around how this is supposed to work, or if what I'm doing is the right thing.

-Alec

[Maxime Lévesque]

I'm trying to think of how this could happen, looked at the code closely...

1) Does this happen only in relations ?
2) If yes, does it happen in OneToMany, ManyToMany or both ?
3) Can you reproduce it consistently (if I send you a patch, can you
run it on a reproduction) ?

Thanks

[Maxime Lévesque]

Also... Just to validate a theory.... The properties that bleed through
the next call, are they by any chance consistently id's (primary keys)
or foreing keys, or are they any random fields ?

Thanks

2010/6/9 Maxime Lévesque <maxime....@gmail.com>:

[Alec Wysoker]

Hi Max,

I don't remember all the cases in which I saw this in the past, but the cases that I've seen recently are OneToMany relations.  I will be selected all the items on the Many side of the relation, e.g. with some code like this:

    val selectedProperties = Set[WorkflowProperty]() ++ workflow.properties

where workflow.properties looks like this:

    ZamboniSchema.workflowToProperties.left(this.asInstanceOf[Workflow])

The SQL generated will look like this:

java.lang.RuntimeException: Exception while executing statement, errorCode: 42122, sqlState: 42S22
Select
  Workflow_Property1.ky as Workflow_Property1_ky,
  Workflow_Property1.id as Workflow_Property1_id,
  Workflow_Property1.prop_Index as Workflow_Property1_prop_Index,
  Workflow_Property1.created_At as Workflow_Property1_created_At,
  Workflow_Property1.value as Workflow_Property1_value,
  Workflow_Property1.workflow_Id as Workflow_Property1_workflow_Id
From
  Workflow_Property Workflow_Property1
Where
  (Step_Property1.value = Workflow_Property1.workflow_Id)

The emboldened part of the where clause is the place where the value for the foreign key should get plugged in.  I can't tell you for certain that this is the only way it has ever happened, but I think so.  I do have a way to reproduce this reliably, and I would be happy to try a patch.

The other thing that occurs to me that might be useful to you is when I was trying to debug this I stuck some code into FieldReferenceLinker to print out a stack trace whenever FieldReferenceLinker._lastAccessedFieldReference was being referenced or set.  If that would be useful to you, I can put that back in there, reproduce the problem, and send you the output.  It might give you a better idea of what is happening.  Let me know if you'd like me to do this.

Thanks, Alec

2010/6/9 Maxime Lévesque <maxime....@gmail.com>

[Maxime Lévesque]

 Alec, this was a bug (...you knew this already ;-)) issue19 :

   http://github.com/max-l/Squeryl/issues/closed#issue/19

it's now fixed in master.

Cheers

[Alec Wysoker]

Hi Max,

That's great. Thanks!

-Alec

2010/6/20 Maxime Lévesque <maxime....@gmail.com>:

[Alec Wysoker]

Hi Max,

I'm afraid I just discovered that the problem hasn't completely
disappeared. When I run a unit test suite with several tests against
a schema that was created once for the whole suite, I still get the
failure:

About to follow relation...
[Mon Jun 21 13:30:11 EDT 2010] INFO:Select

Workflow_Property1.ky as Workflow_Property1_ky,
Workflow_Property1.id as Workflow_Property1_id,
Workflow_Property1.prop_Index as Workflow_Property1_prop_Index,
Workflow_Property1.created_At as Workflow_Property1_created_At,
Workflow_Property1.value as Workflow_Property1_value,
Workflow_Property1.workflow_Id as Workflow_Property1_workflow_Id
From
Workflow_Property Workflow_Property1
Where

(Step_Property1.reference = Workflow_Property1.workflow_Id)

java.lang.RuntimeException: Exception while executing statement,
errorCode: 42122, sqlState: 42S22
Select
Workflow_Property1.ky as Workflow_Property1_ky,
Workflow_Property1.id as Workflow_Property1_id,
Workflow_Property1.prop_Index as Workflow_Property1_prop_Index,
Workflow_Property1.created_At as Workflow_Property1_created_At,
Workflow_Property1.value as Workflow_Property1_value,
Workflow_Property1.workflow_Id as Workflow_Property1_workflow_Id
From
Workflow_Property Workflow_Property1
Where

(Step_Property1.reference = Workflow_Property1.workflow_Id)
at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:250)
at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:299)
at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22)
at org.squeryl.internals.DatabaseAdapter$class.executeQuery(DatabaseAdapter.scala:301)
at org.squeryl.adapters.H2Adapter.executeQuery(H2Adapter.scala:22)
at org.squeryl.dsl.AbstractQuery$$anon$1.<init>(AbstractQuery.scala:110)
at org.squeryl.dsl.AbstractQuery.iterator(AbstractQuery.scala:105)
at org.squeryl.dsl.DelegateQuery.iterator(DelegateQuery.scala:9)
at scala.collection.IterableLike$class.foreach(IterableLike.scala:79)
at org.squeryl.dsl.DelegateQuery.foreach(DelegateQuery.scala:7)
at scala.collection.TraversableOnce$class.foldLeft(TraversableOnce.scala:176)
at org.squeryl.dsl.DelegateQuery.foldLeft(DelegateQuery.scala:7)
at scala.collection.TraversableOnce$class.$div$colon(TraversableOnce.scala:139)
at org.squeryl.dsl.DelegateQuery.$div$colon(DelegateQuery.scala:7)
at scala.collection.generic.Addable$class.$plus$plus(Addable.scala:54)
at scala.collection.immutable.Set$EmptySet$.$plus$plus(Set.scala:47)
at org.broadinstitute.zamboni.server.db.SchemaTest$$anonfun$fieldReferenceLinkerTest$1.apply$mcV$sp(SchemaTest.scala:110)
at org.broadinstitute.zamboni.server.util.TestUtil$$anonfun$executeAndRollback$1.apply(TestUtil.scala:59)
at org.broadinstitute.zamboni.server.util.TestUtil$$anonfun$executeAndRollback$1.apply(TestUtil.scala:58)
at org.squeryl.dsl.QueryDsl$class._using(QueryDsl.scala:40)
at org.squeryl.dsl.QueryDsl$class._executeTransactionWithin(QueryDsl.scala:86)
at org.squeryl.dsl.QueryDsl$class.transaction(QueryDsl.scala:59)
at org.squeryl.PrimitiveTypeMode$.transaction(PrimitiveTypeMode.scala:39)
at org.broadinstitute.zamboni.server.util.TestUtil$.executeAndRollback(TestUtil.scala:58)
at org.broadinstitute.zamboni.server.db.SchemaTest.fieldReferenceLinkerTest(SchemaTest.scala:106)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.testng.internal.MethodHelper.invokeMethod(MethodHelper.java:644)
at org.testng.internal.Invoker.invokeMethod(Invoker.java:546)
at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:700)
at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1002)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:137)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:121)
at org.testng.TestRunner.runWorkers(TestRunner.java:908)
at org.testng.TestRunner.privateRun(TestRunner.java:617)
at org.testng.TestRunner.run(TestRunner.java:498)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:329)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:324)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:296)
at org.testng.SuiteRunner.run(SuiteRunner.java:201)
at org.testng.TestNG.createAndRunSuiteRunners(TestNG.java:915)
at org.testng.TestNG.runSuitesLocally(TestNG.java:879)
at org.testng.TestNG.run(TestNG.java:787)
at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:75)
at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:79)
Caused by: org.h2.jdbc.JdbcSQLException: Column
"STEP_PROPERTY1.REFERENCE" not found; SQL statement:

Select
Workflow_Property1.ky as Workflow_Property1_ky,
Workflow_Property1.id as Workflow_Property1_id,
Workflow_Property1.prop_Index as Workflow_Property1_prop_Index,
Workflow_Property1.created_At as Workflow_Property1_created_At,
Workflow_Property1.value as Workflow_Property1_value,
Workflow_Property1.workflow_Id as Workflow_Property1_workflow_Id
From
Workflow_Property Workflow_Property1
Where

(Step_Property1.reference = Workflow_Property1.workflow_Id) [42122-127]
at org.h2.message.Message.getSQLException(Message.java:110)
at org.h2.message.Message.getSQLException(Message.java:121)
at org.h2.message.Message.getSQLException(Message.java:74)
at org.h2.expression.ExpressionColumn.optimize(ExpressionColumn.java:128)
at org.h2.expression.Comparison.optimize(Comparison.java:146)
at org.h2.command.dml.Select.prepare(Select.java:720)
at org.h2.command.Parser.prepareCommand(Parser.java:236)
at org.h2.engine.Session.prepareLocal(Session.java:417)
at org.h2.engine.Session.prepareCommand(Session.java:378)
at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1066)
at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:73)
at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:233)
at org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:281)
at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:313)
at org.squeryl.internals.DatabaseAdapter$class.prepareStatement(DatabaseAdapter.scala:219)
at org.squeryl.adapters.H2Adapter.prepareStatement(H2Adapter.scala:22)
at org.squeryl.internals.DatabaseAdapter$$anonfun$executeQuery$1.apply(DatabaseAdapter.scala:302)
at org.squeryl.internals.DatabaseAdapter$$anonfun$executeQuery$1.apply(DatabaseAdapter.scala:301)
at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:246)
... 46 more

-Alec

[Maxime Lévesque]

  Ok, I have a diagnosis method for debugging this,
Could you commit your test case in a branch (preferably you rebase it on master's HEAD first),
or send it as patch by email, (whatever is the simplest for you) ?

 Thanks

[Alec Wysoker]

Hi Max,

I might not be able to get to this for a few days, but I will do it.

-Alec

2010/6/21 Maxime Lévesque <maxime....@gmail.com>:

[Alec Wysoker]

Hi Max,

I finally got around to putting all my code into a branch, so that you
could reproduce this problem, but when I try to push it I get an
error:

% git push origin aw_lastAccessedFieldReferenceBleedThrough
Password:
Counting objects: 70, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (54/54), done.
Writing objects: 100% (60/60), 29.58 KiB, done.
Total 60 (delta 28), reused 0 (delta 0)
error: unpack failed: unpack-objects abnormal exit

I know we've talked about this problem before, but I don't remember
what I did last time I got this. Any suggestions?

Thanks, Alec

[Maxime Lévesque]

 If I remember well, you had lost a bunch of time trying to get it to work,
 (it looked like a git+github bug) and you ended up sending the thing as
 a patch.

 Feel free to send it as a patch get... Life is too short to troubleshoot these kinds
 of issues when there are workadounds ;-) Just be sure to tell me what
 is the parent branch and commit ID.

 Thanks !