Evergreen ILS Website

IRC log for #evergreen, 2022-02-09

| 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:01 pinesol News from qatests: Testing Success <http://testing.evergreen-ils.org/~live>
08:28 mantis1 joined #evergreen
08:31 rfrasur joined #evergreen
08:40 mmorgan joined #evergreen
09:09 Dyrcona joined #evergreen
09:09 Dyrcona This bit from a long running search query just doesn't look right: btrim(regexp_replace(translate_isbn1013(naco_norm​alize(split_date_range($_26201$winter$_26201$)))
09:10 Dyrcona translate_isbn1013 wrapped around split_date_range. That's gotta be some kind of a search bug.
09:35 Bmagic agreed, looks wrong
09:38 Dyrcona I'm looking through the apache logs to see if I can find the parameters that caused it.
09:39 jvwoolf joined #evergreen
09:39 miker that's gonna be normalizers attached to whatever field they were searching. it's config. maybe just a side effect of doing a identifier-class search
09:39 Dyrcona Well, this is "new." I was disconnecting a connected USB drive that sometimes errors when being disconnected, and now my trackpad isn't working. Probably gonna have to reboot.
09:41 Dyrcona Bluetooth mouse works, so I'm going to see if some usb module crashed.
09:42 Dyrcona miker: That "side effect" probably kept the query running for over 14 hours, and it would likely never stop unless stopped externally.
09:43 Dyrcona My USB issue looks a bug with LUKS devices. I see it being dismounted in the logs, then udisks tries to access it again.
09:44 miker hrm, seems unlikely that those normalizers would do that, since they should only be run once. it's a constant being passed in, and it's in a cte
09:45 Dyrcona Well, IDK, but it ran for 14 hours and 20 minutes before I canceled it. After I get my laptop sorted, I'm going to get together the relevant details and open a Lp bug. I'll let those smarter than I figure it out.
09:45 miker if you have the whole query, I'd be interested to see it
09:46 Dyrcona I can probably get it from the pg logs. Long-running queries are logged. What I got from pg_stat_activity was only part of the query.
09:47 Dyrcona I'm just gonna reboot. I see lots of fs and driver errors. I think the drive probably jiggled loose before I tried to put it away.
09:50 Dyrcona joined #evergreen
09:51 Dyrcona OK. I'm back. Restart didn't work either. I had to power it off with the button half-way through. This Dell has done that from time to time.....
09:57 Dyrcona So, the query was for "winter sports." What I'm seeing in the Apache logs looks like it might have succeeded.
10:02 terranm joined #evergreen
10:03 Dyrcona So, in the postgresql log when there's something like [42-NN]  where NN is a series of numbers that increase by 1 that means those log lines are related, right?
10:04 mmorgan Dyrcona: That's been my experience
10:05 Dyrcona yeahp. so looks like a 99-line query, then.
10:06 Dyrcona I think I have to go to the brick head to find the apache request. What I see on the syslog server don't look like the actual searches.
10:08 mmorgan Sounds about right for a search query :)
10:10 Dyrcona Well, this is problematic. Looks like they tried a few variations. I'll have to see if I can find the one that caused the problem.
10:11 Dyrcona mmorgan: Unfortunately, yes. I wrote a 250,000 line (give or take) on Monday using a spreadsheet and a Perl program. I was asked to update about 28,000 copies and call numbers.
10:12 Dyrcona Would this part of the query be unique to different variations: $_26201$winter$_26201$ ?
10:13 JBoyer Dyrcona, yeah, the numbers are the pid of some process in the call chain. (I forget which)
10:13 Dyrcona Well, nice! I don't even find that string in the pg logs on the syslog server. UDP is not being helpful.
10:14 * mmorgan thought those numbers were dollar quotes, not pids, which also would not necessarily be unique
10:15 Dyrcona Right, the $_2620$ part is not unique.
10:15 JBoyer They are dollar quotes, using a process pid to make it incredibly unlikely that any possible search term could accidentally or intentionally allow sql injection.
10:16 Dyrcona I had to grep for the _ and number. I think the $ wasn't properly escaped when I tried before.
10:16 mmorgan Ah! Interesting!
10:18 Dyrcona Yeah, I guess this variation of the query didn't make it to the syslogger.... I can't find it in yesterday's logs even when using fixed strings.
10:21 Dyrcona Oh... that shows up in today's logs..... I figured it would be in yesterday's, since it ran for 14+ hours and we log long-running queries after so many minutes.
10:24 Dyrcona So, it's 142 lines...
10:25 Dyrcona miker: You want me to try and srip the pg log cruft off?
10:28 miker (sorry, meeting... feel free to dump the raw log lines if that's easy. I can ctrl-v in vim to cut off chunks)
10:30 Dyrcona S'alright, I cleaned it up already.
10:41 Dyrcona Whee! Just got a spreadsheet with call number updates in UTF-16 because of accents in the labels. Fortunately, it converts to UTF-8.
11:06 collum joined #evergreen
11:09 _collum joined #evergreen
11:09 Dyrcona OK Back to search bugs...
11:15 Dyrcona So, I guess if a query came through websockets, I could see a gateway entry for the query and no apache log entry?
11:17 Dyrcona It's in /var/log/apache2/other_vhosts_access.log. (Well, with the .1 since it's from yesterday.)
11:18 Dyrcona I don't think that makes it to the syslog server.
11:20 Dyrcona It looks like a relatively simple query.
11:34 Dyrcona miker: Bug 1960431
11:34 pinesol Launchpad bug 1960431 in Evergreen "Long-running Qurey from relatively simple search" [Undecided,New] https://launchpad.net/bugs/1960431
11:46 miker Dyrcona: do you think you could get an EXPLAIN for that query, in the db where it got stuck?
11:48 miker (I have a feeling it's the rare-common-rare term pattern, maybe an intersection with pg10)
12:11 Dyrcona miker: I'll get the explain.
12:21 Dyrcona miker: https://bugs.launchpad.net/evergreen/+bug/​1960431/+attachment/5560027/+files/78.plan
12:22 pinesol Launchpad bug 1960431 in Evergreen "Long-running Qurey from relatively simple search" [Undecided,New]
12:34 collum joined #evergreen
12:36 collum joined #evergreen
12:52 jihpringle joined #evergreen
12:56 miker Dyrcona: I assume searching for those terms still spins forever?
13:02 miker nope, or, not really. it's the exact match part. the "'d words
13:03 Dyrcona miker: I haven't tried that search.
13:03 miker looks like we should push the exact match construct down into the initial search structures. I wonder if my "make joins CTEs" patch helps here. I'll dig that up.
13:08 Dyrcona Did they actually type "winter AND sports" in the search box? Do I understand that corectly? I did a keyword from advanced search with winter in one and sports in the other and it came back rather quickly.
13:09 jeff I haven't specifically tested the "make joins CTEs" patch against postgresql < 12 and >= 12, but the change in CTE optimization fence behavior suggests that it might be a good idea (to test/compare). :-)
13:09 Dyrcona Looks like they typed "winter" AND "sports"
13:10 Dyrcona I hate when they try to outsmart the query engine. They usually do with bad consequences. :)
13:11 Dyrcona Yeahp. The variation with the quotes takes longer/hangs. Hasn't been long enough to tell, but the quotes definitely take longer.
13:14 Dyrcona Ha! Looks like they tried again. In addition to my query, I see another running from about 10 minutes earlier.
13:19 Dyrcona It's definitely the double quotes.
13:22 miker Dyrcona: well, I tried it without the and ... sorry :/
13:25 miker anyway, I do think the CTE branch helps, but the exact-match filter would be better right next to the tsquery @@
13:27 Dyrcona miker: Looks like it hangs with or without the AND. I was just trying to reproduce what happened last night.
13:30 Dyrcona miker: Which branch is that? When I grep branch names in the working repo, I only find two from dbs that look relevant.
13:31 miker it may not be pushed to working :(
13:32 miker I'll get (a new version? the first version?) of it out soon and point you at it. I'd have sworn it was floating around, though...
13:35 miker yeah, dbs' was the first step, getting the tsquery construction out of the main select. I do the same to the LEFT JOINs in the main select that represent a search based on each of the dbs CTEs
13:36 miker but I don't see the branch "out there" ... going to search harder, and push one failing that
13:40 miker go git, go!
13:44 jvwoolf joined #evergreen
13:49 Dyrcona :)
14:59 jvwoolf joined #evergreen
16:02 jihpringle joined #evergreen
17:03 jvwoolf left #evergreen
17:10 mmorgan left #evergreen
18:01 pinesol News from qatests: Testing Success <http://testing.evergreen-ils.org/~live>

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