Editing a call number of a cataloged item in the unified editor can result in an uncataloged item

[Michele Morgan]

Evergreen 2.12.4
OpenSRF 2.5.0

This occurs in the xul client. I'm unsure if it's an issue in the web client, but I'm reporting it as a bug because the logs suggest it's more than a client issue.

The issue is intermittent, but when a staff user edits a call number in the unified editor, sometimes the item can end up with -1 in the call_number field.

Viewing the logs shows a new asset.call_number row being created, but the call to retrieve it fails. After a delay, the logs show the copy update, assigning -1 to the call_number field.

The gateway log shows a timeout retrieving the newly created call number:

2017-09-26 15:40:53 brick3 osrf_json_gw: [INFO:167886:osrf_app_session.c:1177:15064548421678862] [open-ils.search] sent 248 bytes of data to router@brick3/open-ils.search
2017-09-26 15:40:53 brick3 osrf_json_gw: [INFO:167886:./osrf_json_gateway.c:328:15064548421678862] [192.168.0.19] [5e4a0d99525949094d7e355ac74e9d0f] [en-US] open-ils.search open-ils.search.callnumber.fleshed.retrieve.authoritative 17932410
2017-09-26 15:41:53 brick3 osrf_json_gw: [INFO:167886:osrf_app_session.c:394:15064548421678862] Returning NULL from app_request_recv after timeout: open-ils.search.callnumber.fleshed.retrieve.authoritative [17932410]
2017-09-26 15:41:53 brick3 osrf_json_gw: [INFO:167886:./osrf_json_gateway.c:435:15064548421678862] Completed processing service=open-ils.search, method=open-ils.search.callnumber.fleshed.retrieve.authoritative

I'm filing this as a separate bug, but adding a link to bug 1704396 because they may have the same root cause.

Captured log entries to follow.

[Michele Morgan (mmorgan)]

Adding a link to a discussion on IRC:

http://irc.evergreen-ils.org/evergreen/2017-10-03#i_328019

Also a database query to identify items that are possible victims of this bug. It uses the auditor.asset_copy_history to find currently uncataloged items that previously had a call number.

select distinct on (cp.id) cp.id as copy_id, cp.deleted as copy_deleted, cp.barcode, hist.call_number as previous_call_number, cp.call_number as current_call_number, cn.record as previous_bib, cn.label as previous_cn_label, cp.edit_date as copy_edit_date from asset.copy cp
join auditor.asset_copy_history hist on cp.id = hist.id
join asset.call_number cn on hist.call_number = cn.id
where cp.call_number < 0
and hist.call_number > 0
order by 1,8

Thanks to Jason Stephenson for refinements to the query.

Also attaching log entries showing the new asset.call_number row being created with id 17932410, but asset.copy is updated with call_number -1 after retrieval of the new call_number id fails.

These entries were found in the gateway log:

2017-09-26 15:40:53 brick3 osrf_json_gw: [INFO:167886:osrf_app_session.c:1177:15064548421678862] [open-ils.search] sent 248 bytes of data to router@brick3/open-ils.search
2017-09-26 15:40:53 brick3 osrf_json_gw: [INFO:167886:./osrf_json_gateway.c:328:15064548421678862] [192.168.0.19] [5e4a0d99525949094d7e355ac74e9d0f] [en-US] open-ils.search open-ils.search.callnumber.fleshed.retrieve.authoritative 17932410
2017-09-26 15:41:53 brick3 osrf_json_gw: [INFO:167886:osrf_app_session.c:394:15064548421678862] Returning NULL from app_request_recv after timeout: open-ils.search.callnumber.fleshed.retrieve.authoritative [17932410]
2017-09-26 15:41:53 brick3 osrf_json_gw: [INFO:167886:./osrf_json_gateway.c:435:15064548421678862] Completed processing service=open-ils.search, method=open-ils.search.callnumber.fleshed.retrieve.authoritative

[Michele Morgan (mmorgan)]

Adding a log thread trace for an occurrence of this that happened on 10/11. This threadtrace contains references to a Jabber layer error in the osrfsys.log:

2017-10-11 08:40:58 brick1 open-ils.search: [INFO:37294:Application.pm:159:1507725612372544] CALL: open-ils.search open-ils.search.callnumber.fleshed.retrieve.authoritative 17936192
2017-10-11 08:40:58 brick1 open-ils.search: [INFO:37294:Event.pm:64:1507725612372544] Loading events xml file /openils/var/data/ils_events.xml
2017-10-11 08:40:58 brick1 open-ils.cstore: [INFO:37095:osrf_app_session.c:1177:1507725612372544] [open-ils.cstore] sent 194 bytes of data to opensrf@brick1-private/open-ils.search_drone_at_brick1.noblenet.org_37294
2017-10-11 08:40:58 brick1 open-ils.cstore: [INFO:37095:osrf_stack.c:163:1507725612372544] Message processing duration 0.000124
2017-10-11 08:40:58 brick1 open-ils.cstore: [INFO:37095:transport_session.c:648:1507725612372544] Received <error> message with type cancel and code 503
2017-10-11 08:40:58 brick1 open-ils.cstore: [WARN:37095:osrf_stack.c:134:1507725612372544] !!! Received Jabber layer error message
2017-10-11 08:40:58 brick1 open-ils.cstore: [WARN:37095:osrf_stack.c:144:1507725612372544] * Jabber Error is for top level remote id [opensrf@brick1-private/open-ils.search_drone_at_brick1.noblenet.org_37294], no one to send my message to! Cutting request short...
2017-10-11 08:40:58 brick1 open-ils.cstore: [INFO:37095:osrf_stack.c:163:1507725612372544] Message processing duration 0.000018
2017-10-11 08:41:04 brick1 open-ils.cstore: [INFO:37095:osrf_prefork.c:496:1507725612372544] No request was received in 6 seconds, exiting stateful session
2017-10-11 08:41:04 brick1 open-ils.cstore: [INFO:37095:osrf_app_session.c:1177:1507725612372544] [open-ils.cstore] sent 196 bytes of data to opensrf@brick1-private/open-ils.search_drone_at_brick1.noblenet.org_37294
2017-10-11 08:41:05 brick1 open-ils.cstore: [INFO:37095:osrf_app_session.c:1177:1507725612372544] [open-ils.cstore] sent 189 bytes of data to opensrf@brick1-private/open-ils.circ_drone_at_brick1.noblenet.org_37273
2017-10-11 08:41:05 brick1 open-ils.cstore: [INFO:37095:osrf_stack.c:163:1507725612372544] Message processing duration 0.001870
2017-10-11 08:41:05 brick1 open-ils.circ: [INFO:37273:CStoreEditor.pm:139:1507725612372544] editor[0|334] request returned no data : open-ils.cstore.direct.action.has_holds_count.retrieve
2017-10-11 08:41:05 brick1 open-ils.circ: [INFO:37273:Transport.pm:163:1507725612372544] Message processing duration: 0.012

Also, from the gateway.log:

2017-10-11 08:40:58 brick1 osrf_json_gw: [INFO:37254:osrf_app_session.c:1177:1507725612372544] [open-ils.search] sent 248 bytes of data to router@brick1/open-ils.search
2017-10-11 08:40:58 brick1 osrf_json_gw: [INFO:37254:./osrf_json_gateway.c:328:1507725612372544] [192.168.0.19] [b5bde9a4ff2f68f21ab45808d0fbec24] [en-US] open-ils.search open-ils.search.callnumber.fleshed.retrieve.authoritative 17936192
2017-10-11 08:41:58 brick1 osrf_json_gw: [INFO:37254:osrf_app_session.c:394:1507725612372544] Returning NULL from app_request_recv after timeout: open-ils.search.callnumber.fleshed.retrieve.authoritative [17936192]
2017-10-11 08:...

[Michele Morgan (mmorgan)]

I'm marking this Invalid as running the above query in our production database retrieves no "victims" from the past few years.