Acq - my selection lists results in database query error

[Ben Shum]

Evergreen version: master

Since http://git.evergreen-ils.org/?p=Evergreen.git;a=commit;h=3149433d354889fba7d7a2338acb55d7d1ffa219 was merged into Evergreen master, it seems that we've lost the ability to use My Selection List to view acquisitions selection lists owned by the user that's logged in. In the staff client, we get a database query error: Event: 2002:DATABASE_QUERY_FAILED -> The attempt to query to the DB failed

Server side, what I'm seeing stuff like this for error log:

2012-03-28 18:13:43 evergreen-test open-ils.cstore: [ERR :529:oils_sql.c:3941:133294861731866204] open-ils.cstore: Malformed FROM clause: extra entry in JSON_HASH

2012-03-28 18:13:43 evergreen-test open-ils.acq: [ERR :541:CStoreEditor.pm:109:133294861731866204] editor[0|2] request error open-ils.cstore.json_query.atomic : {"from":{"acqus":{"acqpl":{"type":"full"},"acqinv":{"type":"full"},"jub":{"type":"full"},"acqpo":{"type":"full"}},"jub":{}},"order_by":[{"direction":"desc","class":"acqpl","field":"edit_time"}],"limit":15,"select":{"acqpl":[{"transform":"distinct","column":"id"},"edit_time"]},"offset":0,"where":{"-and":[{"-or":[{"+au0":{"usrname":"admin"}},{"+au0":{"first_given_name":"admin"}},{"+au0":{"second_given_name":"admin"}},{"+au0":{"family_name":"admin"}},{"+ac0":{"barcode":"admin"}}]}]}} : Exception: OpenSRF::DomainObject::oilsMethodException 2012-03-28T18:13:43 OpenILS::Utils::CStoreEditor /usr/local/share/perl/5.10.1/OpenILS/Utils/CStoreEditor.pm:426 <500> Malformed FROM clause in JSON query

2012-03-28 18:13:43 evergreen-test open-ils.acq: [ERR :541:EX.pm:66:133294861731866204] Exception: OpenSRF::DomainObject::oilsMethodException 2012-03-28T18:13:43 OpenILS::Utils::CStoreEditor /usr/local/share/perl/5.10.1/OpenILS/Utils/CStoreEditor.pm:439 <500> Malformed FROM clause in JSON query

[Ben Shum (bshum)]

Confirmed in IRC on 3/28/12 by kmlussier, berick, and bshum to occur in master installations of Evergreen.

[Bill Erickson (berick)]

One more bit of info:

open-ils.cstore: Invalid table alias "au0" in WHERE clause

[Bill Erickson (berick)]

To clarify, my error above is different from the originally described error. However, it still stands and (I believe) would have occurred with the originally logged query, had the first error not occurred first.

[Tim Spindler (tspindler-cwmars)]

This appears to be happening in 2.2 beta. I just was attempting this on Indiana's test server

[Lebbeous Fogle-Weekley (lebbeous)]

Thanks all for the reports. I have reproduced the problem, and I believe I have fixed it. Can one of you test?

http://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/collab/senator/lp-967824

[Bill Erickson (berick)]

I can confirm that "My Selection Lists" load correctly with the change.

While testing, I realized that my previously mentioned error was the result of a different kind of ACQ search. It's reproducible by searching for "Lineitems" with a single filter of "LI - Selecting User" (of 'admin' in my case). This produces the following error:

 Invalid table alias "au0" in WHERE clause

{"from":{"acqus":{"acqpl":{"type":"full"},"acqinv":{"type":"full"},"jub":{"au0":{"fkey":"selector","class":"au","type":"left","field":"id","join":{"ac0":{"fkey":"card","class":"ac","type":"left","field":"id"}}},"type":"full"},"acqpo":{"type":"full"}}},"order_by":{"jub":{"id":{}}},"limit":15,"select":{"jub":[{"transform":"distinct","column":"id"}]},"offset":0,"where":{"-and":[{"-or":[{"+au0":{"usrname":"admin"}},{"+au0":{"first_given_name":"admin"}},{"+au0":{"second_given_name":"admin"}},{"+au0":{"family_name":"admin"}},{"+ac0":{"barcode":"admin"}}]}]}}

I could open a separate ticket for this, but I'm guessing it's a symptom of the same set of changes to this area of code.

[Lebbeous Fogle-Weekley (lebbeous)]

Aha. Thanks Bill. Force-pushed an amended commit that addresses this problem too.

http://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/collab/senator/lp-967824

[Bill Erickson (berick)]

Verified both fixes. Merged to master and rel_2_2. Thanks!

[Ben Shum (bshum)]

Well, the error is gone, but we still can't retrieve any selection lists. It sits for awhile, while it performs some sort of search but then spits back "no results" each time.

I also tried using the "Reveal Search Form" option and it showed me that I was performing a search for "SL - Owner" on the user I was logged in as. This came back with nothing.

However, when I used date search to find Selection Lists created between 3/1 and 4/1, it gave me at least four lists owned by my user.

Re-opening bug for further scrutiny...

[Lebbeous Fogle-Weekley (lebbeous)]

Ben,

I can't reproduce your issue now.

What's the exact commit hash of the commit you merged into your running system now exhibiting this problem? I'm asking because I wonder if you got the unamended version, since fix in the collab/senator/lp-967824 branch was changed during the day of Apr 3.

If it matches what's in master (or what's in rel_2_2), then next I would ask you to extract the log trace specifically pertaining to a load of the My Selections List interface. As long as you have logging turned up to at least the "info" level, you should be able to see the complete arguments to open-ils.cstore.json_query.atomic that gets generated by the unified search mecanism.

Mine looks like this:

[2012-04-09 10:11:20] open-ils.acq [INFO:8387:CStoreEditor.pm:109:133398043884310] editor[0|1] r
equest en-US open-ils.cstore.json_query.atomic {"from":{"acqus":{"acqpl":{"type":"full","join":{
"au0":{"fkey":"owner","class":"au","type":"left","field":"id","join":{"ac0":{"fkey":"card","clas
s":"ac","type":"left","field":"id"}}}}},"acqinv":{"type":"full"},"jub":{"type":"full"},"acqpo":{
"type":"full"}}},"order_by":[{"direction":"desc","class":"acqpl","field":"edit_time"}],"limit":1
5,"select":{"acqpl":[{"transform":"distinct","column":"id"},"edit_time"]},"offset":0,"where":{"-
and":[{"-or":[{"+au0":{"usrname":"admin"}},{"+au0":{"first_given_name":"admin"}},{"+au0":{"secon
d_given_name":"admin"}},{"+au0":{"family_name":"admin"}},{"+ac0":{"barcode":"admin"}}]}]}}

[Ben Shum (bshum)]

Confirmed that we had the fix, but actually our problem was that the query process took too long to run. The error reported by this bug *was* fixed correctly, so I'm going to change the status back to "fix committed" and then continue other issues in new bug tickets.

Thanks senator, eeevil, etc.