[OPEN-ILS-DEV] ***SPAM*** Re: ***SPAM*** Re: ***SPAM*** Re: 1.4.0.4 -> 1.6.0.3 not a smooth upgrade: not seeing copy summaries
Victoria Bush
vbush at ilstu.edu
Mon Mar 22 16:35:33 EDT 2010
See below for updates.....
On Mar 22, 2010, at 2:46 PM, Dan Scott wrote:
> On 22 March 2010 15:41, Victoria Bush <vbush at ilstu.edu> wrote:
>> This behavior of not seeing the copy status is still showing up in the OPAC, but there doesn't seem to be any rhyme or reason to it. I have run autogen several times, started and stopped the Apache server, and vacuumed the databases in an attempt to isolate the problem. I was able to see copy statuses this morning, then after checking over the system administrator pages in the staff client and making some small tweaks, I decided to play it safe and run autogen and restart Apache. Alas, I'm back to not seeing copy statuses.
>>
>> I am seeing the following error message popping up in several different logs, which may or may not be related:
>>
>>> Use of uninitialized value in join or string at /usr/local/share/perl/5.8.8/OpenSRF/Application.pm line 118.
>>
>> The relevant line in Application.pm, though, is seemingly just a direct to the log file:
>>
>>> $log->info("CALL: $method_name [". (@p ? join(', ', at p) : '') ."]");
>>
>> This error is showing up in:
>>> open-ils.search_unix.log
>>> open-ils.storage_unix.log
>>> open-ils.actor_unix.log
>>> open-ils.circ_unix.log
>>> vandelay_unix.log
>>
>> Now OpenSRF was updated to 1.2.2 per the update instructions, and in testing the connections it seemed to work fine.
>>
>> What information would be most helpful in tracking this down?
>>
>
> A link to your catalogue would be a good start, so we can see if
> anything is turning up in JavaScript calls & check the JavaScript
> generated by autogen.sh
The 1.6.0.3 version can be accessed here (it isn't really searching all of Illinois State, although it says it is):
http://commons.ctlt.ilstu.edu/
It uses a custom skin for colors, but nothing else has been changed; I just copied the default skin and theme over to a new name, ctlt, and edited the colors and updated the eg_vhost.conf file to point to the new skin. No other files were touched or changed; just the colors in the css files. (Alas, not all the colors are in one css file now.)
> More context from the logs would be useful; gateway.log and
> osrfsys.log are probably the most interesting ones.
Some further scouring in osrfsys.log showed something interesting:
> osrfsys.log:[2010-03-22 14:36:23] open-ils.search [ERR :9337:CStoreEditor.pm:104:1269284399890217] editor[0|0] request error open-ils.cstore.direct.serial.record_entry.search.atomic : {"record":10,"deleted":"f"} : Exception: OpenSRF::DomainObject::oilsMethodException 2010-03-22T14:36:23 OpenILS::Utils::CStoreEditor /openils/lib/perl5/OpenILS/Utils/CStoreEditor.pm:370 <500> Severe query error -- see error log for more details
> osrfsys.log:[2010-03-22 14:36:23] open-ils.search [ERR :9337:EX.pm:66:1269284399890217] Exception: OpenSRF::DomainObject::oilsMethodException 2010-03-22T14:36:23 OpenILS::Utils::CStoreEditor /openils/lib/perl5/OpenILS/Utils/CStoreEditor.pm:383 <500> Severe query error -- see error log for more details
> osrfsys.log:[2010-03-22 14:36:23] open-ils.search [INFO:9337:CStoreEditor.pm:104:1269284399890217] editor[0|0] request returned no data : open-ils.cstore.direct.serial.record_entry.search.atomic
> osrfsys.log:[2010-03-22 14:36:24] open-ils.search [INFO:9335:CStoreEditor.pm:104:1269284459893419] editor[0|0] request en-US open-ils.cstore.direct.config.copy_status.search.atomic {"id":{"!=":null}}
> osrfsys.log:[2010-03-22 14:36:24] open-ils.search [INFO:9335:CStoreEditor.pm:104:1269284459893419] editor[0|0] config.copy_status.search : returned 11 result(s)
> osrfsys.log:[2010-03-22 14:36:24] open-ils.search [INFO:1215:CStoreEditor.pm:104:1269284469893915] editor[0|0] request en-US open-ils.cstore.json_query.atomic {"from":["actor.org_unit_ancestor_setting","global.default_locale",1]}
> osrfsys.log:[2010-03-22 14:36:24] open-ils.search [INFO:1215:CStoreEditor.pm:104:1269284469893915] editor[0|0] json_query : returned 0 result(s)
> osrfsys.log:[2010-03-22 14:36:24] open-ils.search [INFO:9335:CStoreEditor.pm:104:1269284399889725] editor[0|0] request en-US open-ils.cstore.direct.biblio.record_entry.retrieve 10
>
There didn't seem to be as much in gateway.log:
> osrf_json_gw 2010-03-22 14:26:17 [ACT:8940:./osrf_json_gateway.c:300:1269284471894012] [127.0.0.1] [] [en-US] open-ils.search open-ils.search.authority.crossref.batch [["series","The Jossey-Bass higher and adult education series"]]
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8940:./osrf_json_gateway.c:300:1269284471894012] [127.0.0.1] [] [en-US] open-ils.search open-ils.search.authority.crossref.batch [["series","The Jossey-Bass higher and adult education series"]]
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8940:osrf_stack.c:119:1269284471894012] Message processing duration 0.000003
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8940:./osrf_json_gateway.c:404:1269284471894012] Completed processing service=open-ils.search, method=open-ils.search.authority.crossref.batch
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8905:osrf_stack.c:119:1269284400890535] Message processing duration 0.000003
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8905:./osrf_json_gateway.c:404:1269284400890535] Completed processing service=open-ils.search, method=open-ils.search.authority.crossref.batch
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8890:osrf_stack.c:119:1269284399889021] Message processing duration 0.000005
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8890:./osrf_json_gateway.c:404:1269284399889021] Completed processing service=open-ils.search, method=open-ils.search.biblio.record_entry.slim.retrieve
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8939:osrf_stack.c:119:1269284469893912] Message processing duration 0.000003
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8939:./osrf_json_gateway.c:404:1269284469893912] Completed processing service=open-ils.search, method=open-ils.search.biblio.multiclass.query
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8900:osrf_stack.c:119:1269284400890027] Message processing duration 0.000003
> osrf_json_gw 2010-03-22 14:26:17 [INFO:8900:./osrf_json_gateway.c:404:1269284400890027] Completed processing service=open-ils.search, method=open-ils.search.biblio.copy_location_counts.summary.retrieve
> osrf_http_translator 2010-03-22 14:29:02 [ACT:8915:./osrf_http_translator.c:280:1269284404891515] [10.133.3.186] [] open-ils.fielder open-ils.fielder.i18n_l.atomic {"query":{"code":{"!=":null}}}
> osrf_http_translator 2010-03-22 14:29:02 [INFO:8915:./osrf_http_translator.c:280:1269284404891515] [10.133.3.186] [] open-ils.fielder open-ils.fielder.i18n_l.atomic {"query":{"code":{"!=":null}}}
> osrf_http_translator 2010-03-22 14:29:02 [INFO:8915:./osrf_http_translator.c:502:1269284404891515] translator resulted in status 0
> osrf_http_translator 2010-03-22 14:36:04 [ACT:8941:./osrf_http_translator.c:280:1269284471894115] [10.133.3.186] [] open-ils.fielder open-ils.fielder.i18n_l.atomic {"query":{"code":{"!=":null}}}
> osrf_http_translator 2010-03-22 14:36:04 [INFO:8941:./osrf_http_translator.c:280:1269284471894115] [10.133.3.186] [] open-ils.fielder open-ils.fielder.i18n_l.atomic {"query":{"code":{"!=":null}}}
> osrf_http_translator 2010-03-22 14:36:04 [INFO:8941:./osrf_http_translator.c:502:1269284471894115] translator resulted in status 0
> osrf_json_gw 2010-03-22 14:36:04 [INFO:8941:osrf_app_session.c:621:1269284471894116] [open-ils.search] sent 297 bytes of data to router at public.localhost/open-ils.search
> osrf_json_gw 2010-03-22 14:36:04 [ACT:8941:./osrf_json_gateway.c:300:1269284471894116] [10.133.3.186] [] [en-US] open-ils.search open-ils.search.biblio.multiclass.query {"org_unit":1,"depth":0,"limit":10,"offset":0,"visibility_limit":3000,"default_class":"keyword"}, "George Bush", 1
> osrf_json_gw 2010-03-22 14:36:04 [INFO:8941:./osrf_json_gateway.c:300:1269284471894116] [10.133.3.186] [] [en-US] open-ils.search open-ils.search.biblio.multiclass.query {"org_unit":1,"depth":0,"limit":10,"offset":0,"visibility_limit":3000,"default_class":"keyword"}, "George Bush", 1
> osrf_json_gw 2010-03-22 14:36:05 [INFO:8941:osrf_stack.c:119:1269284471894116] Message processing duration 0.000006
> osrf_json_gw 2010-03-22 14:36:05 [INFO:8941:./osrf_json_gateway.c:404:1269284471894116] Completed processing service=open-ils.search, method=open-ils.search.biblio.multiclass.query
> osrf_json_gw 2010-03-22 14:36:05 [INFO:8941:osrf_app_session.c:621:1269284471894117] [open-ils.search] sent 203 bytes of data to router at public.localhost
>
> Setting your database to log statements would be good, too; it's often
> set to log nothing by default.
I have mine set to log to /home/postgres/logfile, so I found the following which leads me to believe that the problem is actually upgrading the databases from 1.4.0.4 to the 1.6 format. I see this for most statements:
> ERROR: schema "serial" does not exist
> ERROR: schema "acq" does not exist
which shows up repeatedly in the log:
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 37 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 72 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 28 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 28 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 66 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 195 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 10 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 10 AND "sre".deleted = 'f';
> ERROR: schema "serial" does not exist
> STATEMENT: SELECT "sre".active, "sre".record, "sre".create_date, "sre".creator, "sre".deleted, "sre".edit_date, "sre".editor, "sre".id, "sre".l
> ast_xact_id, "sre".marc, "sre".source, "sre".owning_lib FROM serial.record_entry AS "sre" WHERE "sre".record = 10 AND "sre".deleted = 'f';
>
In looking back at the logfile and looking at the date when I installed Evergreen 1.6, I'm thinking the updating scripts for the databases missed something; I'm seeing a lot of errors for that date, such as
> ERROR: current transaction is aborted, commands ignored until end of transaction block
over and over and over after statements. Should I be concerned that there was no SQL script to update from 1.4.0.4 to 1.4.0.5? I ran the other scripts to get the databases up to 1.6.0.3. I see that the table serial is referenced in the scripts for upgrading from 1.4.0.5 to 1.6 and from 1.6 to 1.6.0.1. The same is true for acq.
I have scads of database backups (dumps of the 1.4.0.4 format), so suggestions are welcome.
>
> --
> Dan Scott
> Laurentian University
--
Victoria Bush
Opscan Evaluation Manager
Center for Teaching, Learning & Technology
vbush at ilstu.edu
More information about the Open-ils-dev
mailing list