[OPEN-ILS-GENERAL] FW: Checkout Problem
Jason Etheridge
jason at esilibrary.com
Wed Jul 21 00:29:36 EDT 2010
> The error which we receive at the Checkout screen and when retrieving patron
> details is below. (I have even tried this at home on both my PC and Mac and
> receive the same error!). Take note, that if you click the 'Ignore Errors'
> button it will ignore the error and take you to the Checkout screen.
Hrmm, we really need to change the way Ignore Errors works or is
labelled. The original intention was to use it for breaking out of
error "loops". It has the potential of allowing an interface to be in
a broken state while masking all the subsequent errors. But in your
case, the network calls that are error-ing out are just informational,
so no harm in Ignoring and continuing there.
> method=open-ils.actor.user.checked_out.count.authoritative
> params=["6e826d7385aa64392feaf87dc3342c06",2]
I seem to recall this method acting up before. It provides a
breakdown of checkouts for the summary sidebar (how many are overdue,
etc.). Yeah, IRC logs show I encountered this in October 2008, but no
other information on what it was or how it was fixed. Are you using
circ scripts or in-db circ rules? It appears I was having some
problem with that as well that day, but can't tell if it's related.
One thing to note about sharing information like this with this list:
that first parameter there is an authentication token (a user session
key), and could be used to gain access to your system if it's still
valid. However, the process of "logging out" of the staff client will
render that session key invalid (which has probably happened by this
point). So that's a good habit to get into (logging out of the
session) if you need to share such information in a public forum.
> THROWN:
> {"payload":[],"debug":"osrfMethodException: ***Call to
> [open-ils.actor.user.checked_out.count.authoritative] failed for session
> [1279585353.065375.12795853534286], thread trave trace [7]:\n Can't use an
> undefined value as an ARRAY reference at
> /openils/lib/perl5/OpenILS/utils/CStoreEditor.pm line 442
> .\n\n","status":500} STATUS:
There should be a corresponding error in the server logs. If you're
not logging to a syslog daemon, they're probably in /openils/var/log/
Try grepping osrfsys.log and gateway.log for the string "[ERR"
You could also tail the logs sometime after business hours (for
lighter log activity) and reproduce the error, and scrutinize what
happens in the logs.
You can run srfsh in another window and use it to invoke just this one
specific method (the staff client will fire off lots of method calls
making the log files very noisy).
opensrf at dev141:/openils/var/log $ srfsh
srfsh# login admin open-ils staff
Received Data: "c8540956fc671470aa8bea8bc6a46a04"
------------------------------------
Request Completed Successfully
Request Time in seconds: 0.012000
------------------------------------
Received Data: {
"ilsevent":0,
"textcode":"SUCCESS",
"desc":"Success",
"pid":15608,
"stacktrace":"oils_auth.c:444",
"payload":{
"authtoken":"8fdfd163ded1e32eccbd674b8dcdcff0",
"authtime":7200
}
}
------------------------------------
Request Completed Successfully
Request Time in seconds: 0.220000
------------------------------------
Login Session: 8fdfd163ded1e32eccbd674b8dcdcff0. Session timeout: 7200.000000
srfsh# request open-ils.actor
open-ils.actor.user.checked_out.count.authoritative
"8fdfd163ded1e32eccbd674b8dcdcff0", 2
Received Data: {
"out":0,
"claims_returned":0,
"long_overdue":0,
"total":0,
"overdue":0,
"lost":0
}
------------------------------------
Request Completed Successfully
Request Time in seconds: 0.296000
------------------------------------
srfsh#
I use the login command in srfsh to get a fresh authtoken, and feed
that to the method call as the first parameter.
In another window I get output like this (using trunk, not 1.6, and I
actually get a lot more output because I have my log levels cranked up
to 4--debug--in opensrf_core.xml):
opensrf at dev141:/openils/var/log $ tail -n 0 -f osrfsys.log
[2010-07-21 00:19:40] open-ils.actor [INFO:28201:Application.pm:118:]
CALL: open-ils.actor.user.checked_out.count.authoritative
[8fdfd163ded1e32eccbd674b8dcdcff0, 1]
open-ils.auth 2010-07-21 00:19:40 [INFO:15599:osrf_prefork.c:686:]
Looking for idle child
from opensrf at private.localhost/open-ils.actor_drone_at_localhost_28201
to opensrf at private.localhost/open-ils.auth_listener_dev141.evergreencatalog.com_1279558991.014015_15599
with body
[{"__c":"osrfMessage","__p":{"api_level":1,"threadTrace":"1","payload":{"__c":"osrfMethod","__p":{"params":["8fdfd163ded1e32eccbd674b8dcdcff0"],"method":"open-ils.auth.session.retrieve"}},"type":"REQUEST","locale":"en-US"}}]
open-ils.auth 2010-07-21 00:19:40 [INFO:15608:oils_auth.c:753:] CALL:
open-ils.auth open-ils.auth.session.retrieve -
["8fdfd163ded1e32eccbd674b8dcdcff0"]
open-ils.auth 2010-07-21 00:19:40 [INFO:15608:oils_event.c:46:]
Creating new event: SUCCESS
open-ils.auth 2010-07-21 00:19:40 [INFO:15608:osrf_app_session.c:968:]
[open-ils.auth] sent 716 bytes of data to
opensrf at private.localhost/open-ils.actor_drone_at_localhost_28201
open-ils.auth 2010-07-21 00:19:40 [INFO:15608:osrf_stack.c:159:]
Message processing duration 0.000000
[2010-07-21 00:19:40] open-ils.storage
[INFO:28202:Application.pm:118:] CALL:
open-ils.storage.actor.user.checked_out.count [1]
[2010-07-21 00:19:40] open-ils.storage [INFO:28202:storage.pm:50:]
Beginning a new transaction with Open-ILS XACT-ID
[1279685980.1420121372.4937771104]
[2010-07-21 00:19:40] open-ils.storage [INFO:28202:storage.pm:156:]
Rolling back a transaction with Open-ILS XACT-ID
[1279685980.1420121372.4937771104]
My postgres logs (with query logging enabled) look like this:
postgres at dev141:/var/log/postgresql$ tail -n 0 -f postgresql-8.3-main.log
2010-07-21 00:22:23 EDT LOG: statement: SET NAMES 'UTF-8';
2010-07-21 00:22:24 EDT LOG: statement: begin
2010-07-21 00:22:24 EDT LOG: statement: SELECT id
FROM action.circulation
WHERE usr = '1'
AND checkin_time IS NULL
AND ( (fine_interval >= '1 day' AND
due_date >= 'today')
OR (fine_interval < '1 day' AND
due_date > 'now' ))
AND (stop_fines IS NULL
OR stop_fines NOT IN
('LOST','CLAIMSRETURNED','LONGOVERDUE'))
2010-07-21 00:22:24 EDT LOG: statement: SELECT id
FROM action.circulation
WHERE usr = '1'
AND checkin_time IS NULL
AND ( (fine_interval >= '1 day' AND
due_date < 'today')
OR (fine_interval < '1 day' AND
due_date < 'now' ))
AND (stop_fines IS NULL
OR stop_fines NOT IN
('LOST','CLAIMSRETURNED','LONGOVERDUE'))
2010-07-21 00:22:24 EDT LOG: statement: SELECT id
FROM action.circulation
WHERE usr = '1' AND checkin_time IS
NULL AND xact_finish IS NULL AND stop_fines = 'LOST'
2010-07-21 00:22:24 EDT LOG: statement: SELECT id
FROM action.circulation
WHERE usr = '1' AND checkin_time IS
NULL AND stop_fines = 'CLAIMSRETURNED'
2010-07-21 00:22:24 EDT LOG: statement: SELECT id
FROM action.circulation
WHERE usr = '1' AND checkin_time IS
NULL AND stop_fines = 'LONGOVERDUE'
2010-07-21 00:22:24 EDT LOG: statement: rollback
This sort of information would be very useful for tracking down what's
going on. Instead of attaching files, you could use
http://paste.lisp.org/new/evergreen and paste the information there.
The resulting URL with your paste will also show up in the #evergreen
IRC channel, so you may want to hang out there for a while when you do
this in case someone is able/willing to help you on the spot.
http://evergreen-ils.org/irc.php
If you do get help in IRC, we should update this email thread with any
solutions for the archive.
Hope this helps!
--
Jason Etheridge
| VP, Tactical Development
| Equinox Software, Inc. / Your Library's Guide to Open Source
| phone: 1-877-OPEN-ILS (673-6457)
| email: jason at esilibrary.com
| web: http://www.esilibrary.com
More information about the Open-ils-general
mailing list