Evergreen ILS Website

IRC log for #evergreen, 2017-10-18

| Channels | #evergreen index | Today | | Search | Google Search | Plain-Text | summary | Join Webchat

All times shown according to the server's local time.

Time Nick Message
06:02 pinesol_green News from qatests: Test Success <http://testing.evergreen-ils.org/~live>
07:22 rjackson_isl joined #evergreen
07:41 dwgreen joined #evergreen
08:16 csharp puzzle of the morning: fines appearing to be from the future
08:17 csharp https://pastebin.com/f2JL6uvp shows what we're seeing
08:19 csharp I can see the fines created during the 14 hour of 10/13 showing timestamps of 10/12 and 10/13, but in the database the billing_ts is 10/13 and 10/14 (with a timestamp of 02:59:59 for some reason)
08:19 csharp wondering if the day boundary is getting crossed somehow?
08:21 csharp date/timezones are correct on all servers involved
08:23 csharp hmm - 02:59:59 - 4 hours is 23:59:59 which is "correct" (though having the timestamps at the end of the day is confusing too)
08:26 csharp PG timezone is 'localtime'
08:29 kmlussier joined #evergreen
08:32 csharp I think I know what's happening
08:32 csharp I think the timezone on the patron's PC is wrong
08:33 csharp 2017-10-12T23:59:59-0700
08:33 csharp -07 is PDT, right?
08:35 csharp 3 hours, not 4
08:35 csharp I think that's the issue
08:35 mmorgan joined #evergreen
08:35 csharp @monologue
08:35 pinesol_green csharp: Your current monologue is at least 14 lines long.
08:38 mmorgan @blame Friday the 13th
08:38 pinesol_green mmorgan: Friday the 13th is why we can never have nice things!
08:40 csharp seriously
08:41 * mmorgan is not sure how the timezone of the patron's pc would factor in.
08:47 csharp mmorgan: I was assuming the work done in bug 1485374 means that the timezone of the PC on which the renewal/checkin/etc. is done is what's used
08:47 pinesol_green Launchpad bug 1485374 in Evergreen "Use client TZ in the database when supplied to the server" [Wishlist,Fix released] https://launchpad.net/bugs/1485374
08:47 csharp that seems to be what happened here, in any case
08:48 mmorgan Ah. ok, missed that.
08:55 Dyrcona joined #evergreen
08:58 * csharp wonders if the fixes for bug 1705524 will resolve his problem
08:58 pinesol_green Launchpad bug 1705524 in Evergreen "Honor timezone of the acting library where appropriate" [Wishlist,Fix released] https://launchpad.net/bugs/1705524
08:58 csharp needing to police patron PCs for timezone settings is gonna be a nightmare
08:59 csharp especially since Windows thinks it's cute to default to Pacific time
09:00 bos20k joined #evergreen
09:06 _adb joined #evergreen
09:07 yboston joined #evergreen
09:09 rjackson_isl csharp: Agreed! BARF!
09:11 rjackson_isl on a more positive note: 3 new branches going live in Evergreen Indiana - today and tomorrow :)
09:14 rhamby rjackson_isl: always good to see growth, best of luck!
09:15 rjackson_isl jboyer and agoben are on site so I think they are in good hands
09:15 csharp rjackson_isl: awesome!
09:16 rjackson_isl Friday the 13th was a 13.5 hour day for me though getting ready
09:38 kmlussier @quote get 179
09:39 Dyrcona pinesol_green: You there?
09:39 pinesol_green Dyrcona: Try restarting apache.
09:39 * kmlussier kicks pinesol_green
09:39 mmorgan Do you have a leading space?
09:40 kmlussier @quote get 179
09:40 pinesol_green kmlussier: Quote #179: "<Bmagic> It's amazing how often 30 days comes around. It's like every 30 days" (added by gmcharlt at 03:36 PM, October 04, 2017)
09:41 kmlussier Yeah, that must have been it.
09:41 mmorgan Heh.
09:41 Dyrcona @quote random
09:41 pinesol_green Dyrcona: Quote #16: "<berick> why's it broken? just bugcause." (added by gmcharlt at 01:37 PM, October 12, 2011)
10:00 kmlussier Sigh...that moment when you realize that the code for the bug fix you're testing isn't actually loaded on the server.
10:00 kmlussier At least I realized it before adding a comment to the LP bug saying that it doesn't work.
10:04 rlefaive_ joined #evergreen
10:12 jvwoolf joined #evergreen
10:16 csharp hmm getting lots of Gateway received error: open-ils.pcrud: permacrud received a bad auth token: <token>
10:16 csharp it's the same one over and over from the same IP
10:17 csharp activity log is open-ils.pcrud open-ils.pcrud.retrieve.mra
10:19 jeff looking for the successful login log entry for that token would likely give you a username as a clue.
10:20 jvwoolf joined #evergreen
10:20 csharp hmm - just a patron
10:21 csharp I wonder what they're trying to do that's generating this
10:22 csharp ... and it stopped
10:22 * csharp moves on, but notes this for the future
10:42 pinesol_green [evergreen|Jeanette Lundgren] DOCS: added tip for patron insensitive search (ignores punctuation) - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=062e439>
10:42 pinesol_green [evergreen|Jane Sandberg] Merge branch 'master' of git.evergreen-ils.org:Evergreen - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=ae595a1>
10:44 Christineb joined #evergreen
10:49 rhamby dbwells++ : for making a buildmaster email entertaining to read
10:54 csharp dbwells++
10:56 gmcharlt dbwells++
10:58 jvwoolf left #evergreen
11:00 Dyrcona Why are call number prefix queries taking 1-1/2 minutes to run?
11:00 collum joined #evergreen
11:00 Dyrcona Correction over 2-3/4 minutes for one of them.
11:01 Dyrcona 14010 | 00:02:36.731063  | 192.168.1.87 | open-ils.cstore  | SELECT "acnp".label AS "call_number_prefix_label", "acnp".id AS "call_number_prefix", "acns".label AS "call_number_suffix_label", "acns".id
11:03 jvwoolf joined #evergreen
11:03 Dyrcona 14010 | 00:04:36.693272  | 192.168.1.87 | open-ils.cstore | SELECT "acnp".label AS "call_number_prefix_label", "acnp".id AS "call_number_prefix", "acns".label AS "call_number_suffix_label", "acns".id
11:03 Dyrcona Yeah, something's broken.... I'll look into it.
11:22 pinesol_green [evergreen|Kyle Huckins] LP#1659181 Mark Items Damaged Prompt - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=373fc3f>
11:30 kmlussier gmcharlt / Bmagic / dbwells: I'm working on maintenance release notes now and plan to have them done before I go to lunch.
11:31 gmcharlt kmlussier++
11:37 Dyrcona So, no one else on 2.12 sees anything like what I mentioned around 11:00?
11:43 mmorgan Dyrcona: I haven't seen that, unless I'm not looking in the right place.
11:43 sandbergja joined #evergreen
11:44 Dyrcona Well, you could see it in the log of long-running queries, or that's a query on the postgres.pg_stat_activity table.
11:44 Dyrcona I've got dozens of those repeated again and again every time I check.
11:45 Dyrcona I've got the full query for one that ran over 2 minutes and I'm going to explain analyze it.
11:45 Dyrcona I think we're missing an index or something.
11:49 cesardv Dyrcona: hey since you're around, do you by any chance remember what was the original cause of bug 1698176? I know it's been a while... sounds like just bad input data?
11:49 pinesol_green Launchpad bug 1698176 in Evergreen "Add New Patron Fails with Wrong Error Message if DB Update Fails" [Undecided,New] https://launchpad.net/bugs/1698176
11:50 mmorgan Dyrcona: Just checked long running queries in the pg_stat_activity and don't see anything related to acnp
11:51 Dyrcona cesardv: The bug is still a bug even if it isn't triggered.
11:51 kmlussier hmmmm...I think some of these fixes recently backported to 3.0 could have been backported to 2.12 as well
11:51 Dyrcona It was triggered by a db-required field having a null value when a patron was added.
11:54 cesardv Dyrcona: right, I was just curious if you or Freddy had been able to pin point the exact field
12:01 stephengwills joined #evergreen
12:01 stephengwills_ joined #evergreen
12:02 jeffdavis joined #evergreen
12:03 stephengwills_ left #evergreen
12:03 stephengwills left #evergreen
12:03 khuckins joined #evergreen
12:05 stephengwills joined #evergreen
12:12 jihpringle joined #evergreen
12:13 jeff cesardv: in the example in the screenshot attached to that bug, it seems to have been an issue with the billing_address. another way to trip the error (at least, i think it's the same error path) is to do something like: 1) create a new permission group, 2) open the new user registration interface, 3) delete the new group before you save the new user, 4) attempt to save the new user
12:13 jeff cesardv: what are you trying to do / answer?
12:15 stephengwills I’m being blocked by a stupid scoping issue in plperlu. would some mind taking a look?
12:15 pastebot "stephengwills" at 64.57.241.14 pasted "Steve's perl scope problem" (23 lines) at http://paste.evergreen-ils.org/861
12:19 cesardv jeff:  sorry lost internet connection on my desktop... arg... can't see the screenshot right now... But yes I'm just trying to reproduce the bug.
12:20 cesardv jeff: ok I'll give your suggestion a try! Thanks
12:22 jeff stephengwills: what are you trying to do? that paste looks incomplete, but i see a few potential issues already.
12:23 jeff (but they may not be issues depending on how the rest of the function)
12:23 miker Dyrcona: what's the full query look like, re your CN affix stuff from above
12:24 jeff stephengwills: oh, i see your comments providing some context.
12:24 stephengwills I just pasted to the fail point.
12:25 jeff stephengwills: your issue is likely on this line: $has300 = '9';
12:25 stephengwills in this funtion, instead of just  has 003 or not, I want to single out CMMC 003s
12:25 stephengwills DOH!
12:25 stephengwills ok sorry to both you :)
12:25 stephengwills bother*
12:25 stephengwills thanks
12:25 jeff you reference $has003 everywhere else, but this assignment is to $has300 -- unless you've declared $has300 elsewhere, i'm surprised this isn't blowing up due to "use strict;"
12:27 stephengwills good point.  strict should be spanking me for that.  but, whatever, its a typo
12:29 stephengwills i’ve been staring at that badboy for half an hour before I asked for help.  dislexics untie!
12:38 Dyrcona cesardv: If you look at my patch, it fixes the error handler to actually do something smart. It doesn't try to address the missing data issue.
12:38 Dyrcona cesardv: The real bug in mind is that the db failure situation does not return what the other modes of the function return.
12:39 Dyrcona miker: I can do 1 better than that. I can paste the full query with explain analyze output just give me a couple of minutes.
12:40 miker Dyrcona: fantastic
12:43 pastebot "Dyrcona" at 64.57.241.14 pasted "Long running query" (81 lines) at http://paste.evergreen-ils.org/862
12:43 Dyrcona miker ^^
12:44 Dyrcona I haven't figured out where in Evergreen it comes from, yet, but I'm assuming the OPAC since it gets run so frequently with different values.
12:49 Dyrcona I'm I reading that correctly and the big killer is the join from acn.id to acp.call_number, or is the time on the line above for the whole chunk that follows?
12:50 Dyrcona s/^I'm/Am/
12:54 rlefaive joined #evergreen
12:55 jeff Dyrcona: looks like OpenILS::WWW::EGCatLoader::mk_copy_query
12:56 Dyrcona jeff: Thanks!
12:57 jeff Dyrcona: are you running into... curses launchpad search...
12:57 Dyrcona My burning question is what to do to fix it? Add an index, analyze the index(es)?
13:02 Dyrcona jeff:  Lp 1527731 ?
13:02 pinesol_green Launchpad bug 1527731 in OpenSRF "Query for OPAC copies can be extremely slow" [Undecided,New] https://launchpad.net/bugs/1527731
13:03 jeff Yep! That's the one that came to mind.
13:03 jeff You might be running the fix for that already, or it might be completely unrelated.
13:03 Dyrcona I installed the Patch for the cache keys yesterday.
13:03 Dyrcona Maybe Lp 1499086 ?
13:03 pinesol_green Launchpad bug 1499086 in Evergreen "Slowness/timeout on loading bookbags in OPAC" [Medium,Incomplete] https://launchpad.net/bugs/1499086
13:04 jeff there is also a general "parts copies are slow" bug, but it seems to have very little activity since being reported + confirmed. bug 1193468
13:04 pinesol_green Launchpad bug 1193468 in Evergreen "Records with many copies with parts load slowly" [Medium,Confirmed] https://launchpad.net/bugs/1193468
13:10 kmlussier gmcharlt / Bmagic / dbwells: Release notes are done.
13:11 pinesol_green [evergreen|Kathy Lussier] Docs: 2.12.7 release notes - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=429b022>
13:11 pinesol_green [evergreen|Kathy Lussier] Docs: 3.0.1 Release notes - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=8a3d8ab>
13:11 jeff Dyrcona: record from the query is 3837620 and org unit id used for ranking is 75. if you use that to suss out a query from web server logs, does it always load this slow?
13:12 Dyrcona I'm trying that now, do I just add &loc_id=75 to set the org_unit?
13:12 jeff the WHERE clause in the query casts a very wide net. the record ID restriction only ends up being mentioned in the ON clause of one of the JOINs. i wonder if that's actually relevant here.
13:13 jeff i was thinking you could use whichever URL params were present in the web server logs for around the time of the original query. i don't know without looking up what you're likely to need to reproduce by hand.
13:14 Dyrcona OK. I see.
13:14 Dyrcona It loads rather quickly if I just load the record.
13:15 jeff looks like the query is bringing along 8M+ copies to the party until the last moment: Rows Removed by Join Filter: 8058958
13:16 jeff https://explain.depesz.com/s/Bq3c
13:16 jeff number 3 there.
13:16 Dyrcona Well, that's not so useful: I can only find HEAD requests for URLs with that record from 11:00 am.
13:16 Dyrcona Yes, I see that.
13:17 Dyrcona After 12, I'm seeing 404s associated with that ID.
13:18 Dyrcona GET /js/dojo/dojo/openils_dojo.js?20e0f1
13:18 Dyrcona That's the "new" cache key after installing the patch for 1527731.
13:19 Dyrcona But, that has nothing to do with the DB query, AFAIK, though the referer was the summary page for that record and the above got a 404.
13:21 Dyrcona mmorgan: What 2.12 version are you on? I'm on 2.12.6. It might help me narrow it down, if I know what release you're on since you don't have this problem.
13:22 mmorgan Dyrcona: 2.12.4
13:22 jeff the planner's estimates are very far off in the near some of the joins on asset.copy and config.copy_status as well as asset.copy and actor.org_unit_descendants. This reminds me a little of some of the issues PINES ran into and Equinox diagnosed/optimized and summarized.
13:22 Dyrcona mmorgan: TYVM
13:22 jeff Dyrcona: did this start after applying the patch for bug 1527731?
13:22 pinesol_green Launchpad bug 1527731 in OpenSRF "Query for OPAC copies can be extremely slow" [Undecided,New] https://launchpad.net/bugs/1527731
13:23 jeff Dyrcona: or did it start when you moved postgresql versions?
13:23 jeff (and what did you move to/from? i forget)
13:23 Dyrcona jeff: It may have, but I can't say for certain. We've had db performance issues ever since the upgrade to 2.12.6, and I don't have good records of what happened before today.
13:24 Dyrcona No, we moved to Pg 9.5 from 9.2 in August.
13:24 kmlussier Is it possible that the query is coming from Syrup? I imagine NOBLE would also see the same issues since they have a similar Syrup setup, but I thought I would mention it.
13:24 Dyrcona kmlussier: It is far too frequent to come from Syrup.
13:24 jeff kmlussier: it looks like a tpac query
13:24 kmlussier Dyrcona: OK, good.
13:25 Dyrcona I had db issues during the upgrade with the replication db running out of disk space.
13:25 Dyrcona I didn't notice any failures on the main db, though.
13:25 jeff Dyrcona: frequency does not rule out it being a syrup query... public course pages getting crawled fire off n*copies requests per load, where n is 2 or 3, i think.
13:26 Dyrcona I seriously doubt an obscure Charles Bronson DVD owned by a public library is in Syrup. :)
13:26 jeff :-)
13:30 kmlussier Dyrcona: Obscure Bronson DVDs could be in Syrup. Owned by a public library? Not so much.
13:32 jvwoolf joined #evergreen
13:35 miker Dyrcona: if you do this in psql: \ef actor.org_unit_descendants(int,int)
13:35 miker there shoudl be a line that says ROWS ... how many rows does it think the function will return?
13:40 * miker finishes reading up and sees jeff read his mind
13:41 Dyrcona That tries to edit the function, and I don't get a line that says ROWS.
13:41 jeff Dyrcona: you can use the \sf variant to avoid firing up your editor
13:42 Dyrcona Oh, STABLE ROWS 1.
13:42 miker cool
13:42 miker so, you'll want to edit the function, and just change ROWS 1 to ROWS 350
13:43 Dyrcona I did that and it goes back to 1.
13:45 miker ok, well, however you want to CREATE OR REPLACE the function, go for it. but adjusting the expected row count may help the planner create a better plan for that expensive branch of the query
13:46 dbwells Dyrcona: did you remember to enter a ';' after saving it?  :)
13:47 Dyrcona I'll try again, but something seems to have chagned. They're running for seconds instead of minutes now.
13:47 * Dyrcona hopes someone isn't poking at the database behind his back.
13:49 kmlussier @who is poking at the database behind Dyrcona's back?
13:49 pinesol_green rlefaive is poking at the database behind Dyrcona's back.
13:49 Dyrcona heh.
13:49 rlefaive Dyrcona caught me poking.
13:49 Dyrcona dbwells++ miker++ It says 350 now.
13:50 miker Dyrcona: explain different?
13:50 Dyrcona I'll see.
13:52 miker wow ... I'm trying to understand the plan that you pasted originally, and why PG thought it sould be a good idea
13:53 Dyrcona I probably need to vacuum analyze the db.
13:54 Dyrcona Yes, the plan is better now. I'll paste it.
13:54 Dyrcona At least, I think it is better now.
13:55 pastebot "Dyrcona" at 64.57.241.14 pasted "Plan2 from db1" (82 lines) at http://paste.evergreen-ils.org/863
13:55 Dyrcona From 3+ minutes down to 30 seconds.
13:57 miker well, it's still refusing to filter by CN first, which is odd, but it's trimming copies sooner. which is an improvement :)
13:57 miker Dyrcona: want to perform another experiment?
13:57 jeff that still looks pretty terrible, but at least the estimates aren't off by 1000x
13:58 Dyrcona miker sure.
13:58 miker show geqo_threshold;
13:59 miker Dyrcona: sorry, that -^ in psql
14:00 Dyrcona qw
14:00 Dyrcona 12
14:00 Dyrcona qw was I had my hand on the wrong row of the keyboard. :)
14:01 miker experiment complete :) ... you could try bumping that up to 13, see if it improves, but I agree that a vac on the relevant tables is a better starting place
14:08 miker Dyrcona: can you grab an explain analyze of this: http://paste.evergreen-ils.org/864
14:08 miker it's just a reordered join
14:12 pastebot "Dyrcona" at 64.57.241.14 pasted "Plan for re-ordered query" (60 lines) at http://paste.evergreen-ils.org/865
14:13 Dyrcona It's a lot better.
14:14 jeff no more seq scan on acp.
14:15 jeff no more 720 MB Hash
14:15 Dyrcona I'm going to do an analyze on the whole db.
14:15 Dyrcona Then try the original query again.
14:21 Dyrcona This analyze may have to wait until "after hours" tonight.
14:21 * Dyrcona is feeling a bit gun shy.
14:40 jvwoolf Anybody running StackMap in their catalog?
14:42 kmlussier The StackMap sales rep at ALA told me somebody on Evergreen is using StackMap. For some reason, I think she said it was a library in Connecticut.
14:42 kmlussier But I could be misremembering.
14:42 jvwoolf LOL
14:42 jvwoolf Well, they are right, but we just got the code
14:43 csharp "oh, sure it works with Evergreen!"
14:43 jvwoolf I have an idea of where to put it, but wanted to check
14:44 rhamby "our product works with everything, don't worry" - said nearly every sales rep ever
14:45 kmlussier jvwoolf: She made it sound like you all had it up and running. :D
14:48 jvwoolf kmlussier: That's why she makes the big bucks :)
15:01 csharp kmlussier: btw, I met "the other" Kathy Lussier a couple of weeks ago at the Georgia Libraries Conference
15:02 kmlussier csharp: Did you? I still haven't met her yet!
15:02 csharp she's with... whatever that libary email notices company is
15:02 kmlussier csharp: I thought she was with Novelist.
15:02 csharp did a double take when I saw her nametag
15:02 kmlussier Unless there is a third Kathy Lussier working in libraries. :(
15:02 csharp heh
15:03 kmlussier They're multiplying!
15:03 csharp there's a Chris Sharpe who works at a local university that I'm always getting confused with, esp. at that conference
15:04 berick Ye Olde Chris Sharpe
15:04 csharp lol
15:04 kmlussier Yeah, somebody at ALA once tried merging our ALA online accounts because she thought I had accidentally created two different accounts.
15:05 csharp @blame overzealous deduplication
15:05 pinesol_green csharp: Forget it, Jake. It's just overzealous deduplication.
15:05 csharp @band add Overzealous Deduplication
15:05 pinesol_green csharp: Band 'Overzealous Deduplication' added to list
15:06 csharp we had UMS do a patron DB cleanup a few years ago - it's amazing how many people in Georgia have the same 1) first name 2) last name and 3) DOB
15:07 kmlussier That's just weird.
15:08 csharp we were getting enough that I automated it with an "unmerge" script
15:10 kmlussier Back when I was a newspaper reporter, there was some notable crime committed by a couple with the exact same names as a well-known couple in town who ran a restaurant. We always used middle initials when we used names in news articles, but they even had the same middle initials.
15:11 kmlussier They had to write this big disclaimer at the bottom of the article making it clear that they weren't the same people.
16:37 khuckins joined #evergreen
17:01 jvwoolf left #evergreen
17:10 mmorgan left #evergreen
17:16 yboston joined #evergreen
17:52 pinesol_green [evergreen|Dan Wells] Fix stray beta1 in 3.0.0 upgrade script - <http://git.evergreen-ils.org/?p=​Evergreen.git;a=commit;h=e2ebc52>
18:00 pinesol_green News from qatests: Test Success <http://testing.evergreen-ils.org/~live>

| Channels | #evergreen index | Today | | Search | Google Search | Plain-Text | summary | Join Webchat