Manual Search Crashes LazyLibrarian

[PeteJB]

Hi,

I have a problem with the manual search in LazyLibrarian. When I click on manual under a book, it opens a new tab (with nothing in it) and LazyLibrarian crashes and restarts.

I have pasted part of the log. The last message was at 17:02:54. I waited approximately 5 minutes before clicking on manual and the next message is at 17:08:15

To help with identifying and fixing issues, please include as much information as possible, including:

LazyLibrarian version number (at the bottom of config page)

Current Version: 1c112dd

Operating system used (windows, mac, linux, NAS type)

Alpine Linux. Running in a docker.

Interface in use (default, bookstrap)

bookstrap

Which api (Goodreads, GoogleBooks, both)

Goodreads

Source of your LazyLibrarian installation (git, zip file, 3rd party package)

Thraxis Docker: https://hub.docker.com/r/thraxis/lazylibrarian-calibre/

Relevant debug log with api keys and any passwords redacted

08-Jan-2018 17:02:54 - DEBUG :: MAIN : LazyLibrarian.py:main:163 : Current Version [1c112dd] - Latest remote version [b0f8c37] - Install type [git]
08-Jan-2018 17:02:54 - INFO :: MAIN : LazyLibrarian.py:main:198 : Starting LazyLibrarian on port: 5299, webroot ""
08-Jan-2018 17:02:54 - INFO :: MAIN : webStart.py:initialize:59 : Starting LazyLibrarian web server on http://0.0.0.0:5299/
08-Jan-2018 17:02:54 - DEBUG :: MAIN : common.py:scheduleJob:292 : Start processDir job in 10 minutes
08-Jan-2018 17:02:54 - DEBUG :: MAIN : common.py:scheduleJob:305 : Start search_book job in 360 minutes
08-Jan-2018 17:02:54 - DEBUG :: MAIN : common.py:scheduleJob:299 : Start search_magazines job in 360 minutes
08-Jan-2018 17:02:54 - DEBUG :: MAIN : common.py:scheduleJob:316 : Start checkForUpdates job in 24 hours
08-Jan-2018 17:02:54 - DEBUG :: MAIN : common.py:scheduleJob:344 : Start authorUpdate job in 55 hours
08-Jan-2018 17:08:15 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1009 : getBookCover: Returning Cached response for /config/cache/book/97888.jpg
08-Jan-2018 17:08:21 - INFO :: MAIN : init.py:initialize:555 : Log level set to [3]- Log Directory is [/config/log] - Config level is [3]
08-Jan-2018 17:08:21 - INFO :: MAIN : init.py:initialize:557 : Screen Log set to EXTENDED DEBUG

Please note - usually a single line of log is not sufficient. The lines just before the error occurs can give useful context and greatly assist with debugging.

There is a built-in debug log creator on the logs page which makes it easy to provide this information

• To use it, first go to the log page and make sure debug logging is OFF
• Now press the "Start debug log" button
• Go and do whatever you need to recreate the error
• Go back to the log page and press "Save debug log"
• You can now turn debug logging off again if you want
• The saved log file will be found in your lazylibrarian log directory called debug.zip
• It will contain all lines logged since you pressed "Start debug log" with any passwords and api keys removed
• Attach the zip file to your bug report.

[philborman]

Seems to be crashing trying to get the book covers. In the manual edit page we try to collect a few different covers so we can give a choice of which to use. I will have a look at this later today, might need to add some more debugging messages to track progress through the various covers.

[PeteJB]

Great. Thanks for the help.

[philborman]

Just pushed a new version with some extra debugging to hopefully track this down

[PeteJB]

Thanks. I've requested the docker be updated to include the new level of code. Hopefully that will happen soon. If not, I will install a different docker that gets updated weekly.

I'll updated this issue with a new debug (hopefully within a week).

[philborman]

You should be able to upgrade the lazylibrarian version from inside the docker, there is a "check version" button on the lazylibrarian config page that will offer an upgrade if available, unless the docker creator has disabled it

[PeteJB]

Thanks, updated to the latest version:
Repo: https://github.com/dobytang/lazylibrarian : Branch: master
Current Version: 7b736aa : Latest Version: 7b736aa

1. Restarted LazyLibrarian and let it settle for about 10 minutes
2. Click on an author
3. In the title column, clicked on the word manual

Here is the results:
Note: 21:53 is the last log message before, after the restart and letting it sit. 22:02 is when I did steps 2 and 3 above. It looks like it started to get the bookcover and then LL restarted itself.

10-Jan-2018 21:53:58 - DEBUG :: MAIN : common.py:scheduleJob:316 : Start checkForUpdates job in 24 hours
10-Jan-2018 21:53:58 - DEBUG :: MAIN : common.py:scheduleJob:344 : Start authorUpdate job in 45 hours
10-Jan-2018 22:02:47 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting current cover for 36553385
10-Jan-2018 22:02:47 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1014 : getBookCover: Returning Cached response for /config/cache/book/36553385.jpg
10-Jan-2018 22:02:47 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting cover cover for 36553385
10-Jan-2018 22:02:47 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting goodreads cover for 36553385
Lazylibrarian is starting up...
10-Jan-2018 22:02:54 - INFO :: MAIN : init.py:initialize:555 : Log level set to [3]- Log Directory is [/config/log] - Config level is [3]
10-Jan-2018 22:02:54 - INFO :: MAIN : init.py:initialize:557 : Screen Log set to EXTENDED DEBUG
10-Jan-2018 22:02:54 - DEBUG :: MAIN : init.py:check_setting:509 : Newznab0 : enabled -> True

[philborman]

ok so it looks like it gets stuck fetching a cover from goodreads. Fetches the first two ok. Doesn't seem to be crashing, just getting stuck.
I will have another look and see if I can see where the problem is. At least we've narrowed it down a bit...

[philborman]

I've just pushed an update, reorganised the cover creation. It's possible an invalid or missing goodreads link could have caused problems, added a few more debugging messages too.

[PeteJB]

Hi. Thanks for the update. Unfortunately it's still not working. Here's the latest log messages:

11-Jan-2018 18:38:37 - DEBUG :: MAIN : versioncheck.py:logmsg:41 : Update check complete
11-Jan-2018 18:38:37 - DEBUG :: MAIN : LazyLibrarian.py:main:163 : Current Version [905ba68] - Latest remote version [905ba68] - Install type [git]
11-Jan-2018 18:38:37 - INFO :: MAIN : LazyLibrarian.py:main:198 : Starting LazyLibrarian on port: 5299, webroot ""
11-Jan-2018 18:38:37 - INFO :: MAIN : webStart.py:initialize:59 : Starting LazyLibrarian web server on http://0.0.0.0:5299/
11-Jan-2018 18:38:37 - DEBUG :: MAIN : common.py:scheduleJob:292 : Start processDir job in 10 minutes
11-Jan-2018 18:38:37 - DEBUG :: MAIN : common.py:scheduleJob:305 : Start search_book job in 360 minutes
11-Jan-2018 18:38:37 - DEBUG :: MAIN : common.py:scheduleJob:299 : Start search_magazines job in 360 minutes
11-Jan-2018 18:38:37 - DEBUG :: MAIN : common.py:scheduleJob:316 : Start checkForUpdates job in 24 hours
11-Jan-2018 18:38:37 - DEBUG :: MAIN : common.py:scheduleJob:344 : Start authorUpdate job in 45 hours
11-Jan-2018 18:48:31 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting current cover for 32075854
11-Jan-2018 18:48:31 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1014 : getBookCover: Returning Cached response for /config/cache/book/32075854.jpg
11-Jan-2018 18:48:31 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting cover cover for 32075854
11-Jan-2018 18:48:31 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1041 : getBookCover: No cover.jpg found for 32075854
11-Jan-2018 18:48:31 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting goodreads cover for 32075854
11-Jan-2018 18:48:36 - INFO :: MAIN : init.py:initialize:555 : Log level set to [3]- Log Directory is [/config/log] - Config level is [3]
11-Jan-2018 18:48:36 - INFO :: MAIN : init.py:initialize:557 : Screen Log set to EXTENDED DEBUG
11-Jan-2018 18:48:36 - DEBUG :: MAIN : init.py:check_setting:509 : Newznab0 : enabled -> True

[philborman]

Still getting stuck inside the goodreads request. I'm struggling to see how/why.
Do you know how to log into your docker over ssh, and are you up for a little editing to try and find the problem?

[PeteJB]

Hi Phil,

No probs getting into the container. Not sure what editor is packaged with it, but I can always copy the file out, edit and copy it back in if I need.

Thanks
Pete

[philborman]

Probably nano
Make sure you keep a copy of the unmodified original bookwork.py so you can put it back later.

All we need really are some checkpoints in the goodreads cover routine showing how far we get before it gets stuck. That should show where the problem is, then it's a matter of working around it.
I've attached a new version of bookwork.py with the checkpoints already built in
Will be interesting to see the CHECKPOINT lines in the log

bookwork.zip

[PeteJB]

Hi.

Latest log file below.

11-Jan-2018 23:55:55 - INFO :: MAIN : webStart.py:initialize:59 : Starting LazyLibrarian web server on http://0.0.0.0:5299/
11-Jan-2018 23:56:15 - INFO :: CONFIG_WRITE : init.py:config_write:991 : Config file [/config/config.ini] has been updated
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting current cover for 36553385
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1014 : getBookCover: Returning Cached response for /config/cache/book/36553385.jpg
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting cover cover for 36553385
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1041 : getBookCover: No cover.jpg found for 36553385
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1005 : Getting goodreads cover for 36553385
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1085 : CHECKPOINT 1, looking for bookid 36553385
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1091 : CHECKPOINT 2, found 3
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1093 : CHECKPOINT 3, booklink [https://www.goodreads.com/book/show/36553385-hari-and-his-electric-feet]
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1100 : CHECKPOINT 4, params ready
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1104 : CHECKPOINT 5, goodreads present in booklink
12-Jan-2018 00:00:19 - DEBUG :: EDIT_BOOK : bookwork.py:getBookCover:1115 : CHECKPOINT 6, fetching url
12-Jan-2018 00:00:26 - INFO :: MAIN : init.py:initialize:555 : Log level set to [3]- Log Directory is [/config/log] - Config level is [3]
12-Jan-2018 00:00:26 - INFO :: MAIN : init.py:initialize:557 : Screen Log set to EXTENDED DEBUG
12-Jan-2018 00:00:26 - DEBUG :: MAIN : init.py:check_setting:509 : Newznab0 : enabled -> True

[philborman]

Well that's interesting. We go off to fetch the URL and never return.
The URL [https://www.goodreads.com/book/show/36553385-hari-and-his-electric-feet] looks ok
so not sure what's going on. Do you have any warnings at startup about missing modules? Could be the python in your docker doesn't have ssl support, although I would have thought we should get an error back from fetching the url.
If you save the debug log from inside lazylibrarian log page it will create a file debug.zip. The first section of that file gives details on software versions installed, including the ssl stuff.

[PeteJB]

yep. will do a shutdown, clean startup and edit for passwords, api's etc and add here shortly