| Time |
Nick |
Message |
| 01:35 |
|
kworstell_isl_ joined #evergreen |
| 04:06 |
|
scottangel joined #evergreen |
| 04:06 |
|
dluch joined #evergreen |
| 04:06 |
|
Bmagic joined #evergreen |
| 06:51 |
|
redavis joined #evergreen |
| 07:16 |
|
kworstell-isl joined #evergreen |
| 07:16 |
|
kworstell_isl joined #evergreen |
| 08:01 |
|
BDorsey joined #evergreen |
| 08:35 |
|
mmorgan joined #evergreen |
| 08:44 |
|
Dyrcona joined #evergreen |
| 08:45 |
|
mantis joined #evergreen |
| 08:52 |
|
dguarrac joined #evergreen |
| 09:16 |
|
stephengwills joined #evergreen |
| 09:19 |
Dyrcona |
Whee! 47GB of syslog to wade through for two errors. |
| 09:24 |
Rogan |
spelunking time! |
| 09:25 |
Dyrcona |
It's greppin' time! |
| 09:27 |
Dyrcona |
I've got timestamps and process ids to look for. Grep for 'ERR :' so far turns up potentially unrelated stuff. |
| 09:27 |
stephengwills |
the SIP server looks like it sends the consortium name, not the library name when returning patron status. Is that a configuration option? |
| 09:30 |
Dyrcona |
stephengwills: OTTOMH, I think it's returning the institution from the oils_sip.xml for the account. If it's not set, it sends the top level. I'd have to look at the code again to be sure, and I'm looking into something else at the moment. |
| 09:31 |
Dyrcona |
This is a new on on me: Mar 14 04:11:04 egtest /openils/bin/action_trigger_runner.pl: [ERR :9974:AppSession.pm:132:] Attempting to build a client session as a server Session ID [1710403861.827438279.98900141986], remote_id [opensrf private.localhost/opensrf.settings_drone_at_localhost_3463] |
| 09:33 |
stephengwills |
np, thanks. I see what’s going on now. AO is fixed when ILS is constructed. I just had a request from a vendor to pin a patron to it’s home_ou which doesn’t appear to be a feature…. yet. |
| 09:34 |
Dyrcona |
stephengwills: home_ou is returned somewhere, a non-standard field, I think. Have a look in Open-ILS/src/perlmods/lib/OpenILS/SIP/Patron.pm. |
| 09:39 |
Dyrcona |
Oh! It found something. I'll have to grep again with just the process id. |
| 09:40 |
Dyrcona |
It also looks like it may not be the typical problem with hooks that I've seen before. This looks different. |
| 09:41 |
Dyrcona |
Looks like one of the multi-line log entries. I'll have to add -A with a couple of lines. |
| 09:51 |
stephengwills |
Future home Players: the home library for a patron is in the AQ field. |
| 10:23 |
|
sandbergja joined #evergreen |
| 10:32 |
Dyrcona |
"<500> *** Call to [open-ils.circ.renew] failed for session [1710408674.85611053.4698097936], thread trace [1]" is that 'thread trace [1]' supposed to correspond to anything, like a PostgreSQL log thread trace? |
| 10:33 |
|
kworstell-isl joined #evergreen |
| 10:35 |
|
kworstell_isl joined #evergreen |
| 10:57 |
|
jihpringle joined #evergreen |
| 10:58 |
csharp_ |
Dyrcona: line 250 of OpenSRF/src/perl/lib/OpenSRF/Application.pm |
| 10:59 |
csharp_ |
(assuming you haven't already gotten there 30 mins later ;-) ) |
| 11:12 |
|
redavis_reboot joined #evergreen |
| 11:48 |
|
jihpringle joined #evergreen |
| 11:53 |
Dyrcona |
This is frustrating. What I see in production is usually a failure to create the AutorenewNotify event because of a failure to get the hooks. What I got in testing last night is a failure to renew two items. |
| 11:54 |
Dyrcona |
csharp_: Thanks! I'm not sure what I posted is related to what I'm actually trying to solve. I just saw that and it looked weird. |
| 12:13 |
Dyrcona |
So, looks like there was no database transaction or a failure to create one in my test last night. |
| 12:15 |
Dyrcona |
245378849:Mar 14 05:31:28 egtest open-ils.circ: [ERR :22856:CStoreEditor.pm:155:] editor[1|1741616] request error open-ils.cstore.direct.action.circulation.create : <new object> : Exception: OpenSRF::DomainObject::oilsMethodException 2024-03-14T09:31:28 OpenILS::Utils::CStoreEditor /usr/local/share/perl/5.30.0/OpenILS/Utils/CStoreEditor.pm:481 <400> No active transaction -- required for CREATE |
| 12:32 |
Dyrcona |
This is interesting. It looks like the CStoreEditor opened a transaction at 5:31:14 to work on a different circulation. At 5:31:28 the same(?) editor was asked to create a new circulation, but there was no transaction. At 5:31:30 the previously opened transaction was committed. |
| 12:36 |
Dyrcona |
The CStoreEditor messages are all coming from the same circ drone, so I assume it's the same CStoreEditor instance. |
| 12:57 |
Dyrcona |
One of the two error transactions actually renewed and had the AutorenewNotify event created, but I still see no reason in the logs for it to have been set to the error state. It was not being handled by the same circulation drone as the one that got no transaction. |
| 13:03 |
|
jvwoolf joined #evergreen |
| 13:30 |
|
mantis1 joined #evergreen |
| 13:42 |
Dyrcona |
One thing: Setting the loglevel to 4 was NOT useful. The extra messages were mostly redundant with the INFO (3) messages. |
| 13:43 |
|
jihpringle joined #evergreen |
| 14:07 |
* Dyrcona |
wonders if 5 does anything. I seem to recall it used to add something.... Checks the code.... |
| 14:09 |
|
mantis joined #evergreen |
| 14:12 |
Dyrcona |
Yeah, $logger->internal(), but that would be seriously way too much information. |
| 14:13 |
|
jweston joined #evergreen |
| 14:14 |
|
jeff joined #evergreen |
| 14:14 |
Dyrcona |
Looks like it would log the content of just about every message sent through OpenSRF. |
| 14:33 |
|
kworstell_isl_ joined #evergreen |
| 14:35 |
|
kworstell-isl joined #evergreen |
| 14:38 |
Dyrcona |
So, it looks like some drone got hung up. The circ drone that was processing the successful renewal logged the renewal at 5:31:14 and there were a few related messages, then nothing from that drone in the logs until 5:31:29 when the AppSession shut down and flushed XMPP data. |
| 14:45 |
Dyrcona |
The cstore drone that did the database updates went on to other things after it was done. |
| 14:46 |
Dyrcona |
Backlog queue never filled up either. |
| 14:49 |
Dyrcona |
"What we have here is a failure to communicate." |
| 14:52 |
Dyrcona |
ejabberd.log has no errors, etc. |
| 14:55 |
Dyrcona |
The other one couldn't get a transaction as I mentioned earlier, and it looks like that cstore drone was trying to process 2 different circulations at the same time. |
| 15:17 |
|
kworstell_isl joined #evergreen |
| 15:19 |
|
kworstell_isl_ joined #evergreen |
| 15:29 |
|
mantis left #evergreen |
| 15:52 |
|
kworstell_isl joined #evergreen |
| 15:55 |
|
kworstell-isl joined #evergreen |
| 16:36 |
|
jihpringle joined #evergreen |
| 16:56 |
|
jihpringle joined #evergreen |
| 17:05 |
|
mmorgan left #evergreen |
| 17:08 |
|
stephengwills left #evergreen |
| 17:19 |
jeffdavis |
we're seeing a few instances where multiple checkout receipt events are being generated for the same circ |
| 17:20 |
Bmagic |
jeffdavis: the double click? |
| 17:21 |
Bmagic |
or maybe a slow/packet loss internet connection where TCP retries? And the other packets arrive anyway. Does PCRUD retry? |
| 17:23 |
jeffdavis |
In the most recent example, I see 2 open-ils.cstore.direct.action_trigger.event.create calls 5 seconds apart. |
| 17:24 |
jeffdavis |
I had a few incidents a couple day ago where some circs generated like 480 checkout receipt events. |
| 17:24 |
Bmagic |
that rules out TCP retries. It's the JS |
| 17:47 |
jeffdavis |
bug 2057974 |
| 17:47 |
pinesol |
Launchpad bug 2057974 in Evergreen "Checkout can generate multiple checkout receipt events" [Undecided,New] https://launchpad.net/bugs/2057974 |
| 20:31 |
|
sleary joined #evergreen |
| 21:21 |
|
stephengwills_ joined #evergreen |
| 22:09 |
|
sleary joined #evergreen |
