Kobo Sync fails - Githubissues

Kobo Sync on YNH Calibre Web fails

Firstly, let me just thank the devs who are porting calibre-web to ynh, I really appreciate all this work!

Hi, I recently installed calibreweb on my ynh instance in hopes to sync my kobo device with that library. Unfortunately, after following the configuration steps, the sync fails

Context

Hardware: Old computer (bare-metal amd64)
YunoHost version: 11.1.18 (stable)
I have access to my server: Through SSH and through web-admin
Are you in a special context or did you perform some particular tweaking on your YunoHost instance?: no
Using, or trying to install package version/branch: Installed version: 0.6.20~ynh1

Steps to reproduce

Tick 'Enable Kobo Sync' in calibre-web admin > basic configuration > feature configuration
Server external port set to 443 (calibre-web is served via a LetsEncrypt singned subdomain (https://library.domain.tld)
in user settings section (not Admin section) click button create/view under 'Kobo Sync Token' which displays a modal with configuration information, described in following step
on the Kobo device itself, add the api_endpoint= line to the .kobo/Kobo/Kobo eReader.conf file
eject Kobo device and press the sync button on the eReader device, top right of the 'Home' screen.
Task fails after about 15 seconds of the sync icon spinning. Dialog says 'Sync to download new items and software updates' button on that modal says 'Retry sync'.

Expected behavior

I expected the Kobo device to connect to my calibre-web library and download the KEPUB books that are available there or alternatively sync from a selected shelf (I have tried both and neither work).

Logs

Full Calibreweb log (since app installation): https://paste.yunohost.org/faboyuravu.swift Full Calibreweb-access log (all I have): https://paste.yunohost.org/uwujokuyot.php

Additional information / attempts

I have tried the various methods outlined in this ynhforum thread https://forum.yunohost.org/t/synchronisation-kobo/21590 which seems to be unresolved

I was having a weird looking list of log errors that suggested to me that my epubs were missing metadata;

[2023-05-02 10:02:29,248] ERROR {cps.db:848} Author  not found to display name in right order
[2023-05-02 10:02:36,700] ERROR {cps.db:848} Author  not found to display name in right order
[2023-05-02 10:02:43,461] ERROR {cps.db:848} Author  not found to display name in right order
[2023-05-02 10:02:51,713] ERROR {cps.db:848} Author  not found to display name in right order
[2023-05-02 10:02:52,973] ERROR {cps.db:848} Author  not found to display name in right order

so I thought that that might be causing the issue, so I deleted all my books from calibreweb and only reuploaded one epub (which converted automatically to kepub) where the metadata looks immaculate, but this did not change anything.

I can see that the content of my library is indeed being served when I add /v1/library/sync to the end of the api_endpoint url and visit it in my browser
I have made sure that All users and Visitors are allowed to access Calibre-web and Calibre-web (Kobo Sync) apps from the ynh web admin
I have used the 'force full kobo sync' button multiple times, to no effect
I have also tried deleting the token and reissuing it, but no success
Triggering the sync on the kobo returns a Sync Failed screen, see the photo below.

Thank you for any support you could provide!

Best regards

Hello and thanks for the detailed report, I myself also struggled to make it work asks I have the feeling that it was sheer luck... Looking at the logs, I can see 3 things:

the access log is giving a 200 return code, so this is not a network/proxy issue

when you force full kobo sync, it seems that some kepub were considered as synched by calibreweb:

[2023-05-04 11:18:09,161]  INFO {cps.ub:898} 1 sync entries deleted
[2023-05-04 11:26:04,453]  INFO {cps.kobo:1066} Init
[2023-05-04 11:28:50,077]  INFO {cps.ub:898} 0 sync entries deleted
[2023-05-04 11:29:01,340]  INFO {cps.kobo:1066} Init

This line seems to indicate that something strange happens when you request a sync:

[2023-05-03 14:07:40,783]  INFO {cps.kobo:143} Kobo library sync request received.
[2023-05-03 14:07:41,025]  WARN {py.warnings:109} /var/www/calibreweb/cps/kobo.py:264: SAWarning: SELECT statement has a cartesian product between FROM element(s) "archived_book" and FROM element "anon_1".  Apply join condition(s) between each element to resolve.
max_change = changed_entries.from_self().filter(ub.ArchivedBook.is_archived)\

So, at first sight, I would say that it is an upstream bug and not a packaging one. Can you activate the debug log in the main configuration of calibreweb and retry to see if we can gather more information?

Thanks @Krakinou

Looking to activate debug logs, but I can't see any button for that, is that something I can access outside of Calibre itself, via ssh maybe?

Cheers

Sorry, I found it, I was looking for a checkbox to enable, and not a dropdown to toggle the log levels.

In the meantime, something really weird was happening whereby I could not login to my calibreweb instance. All the other apps on my ynh instance (including the webadmin) all worked fine and I could log in, but not on calibre web. So I reinstalled it (I only had one book in it) and the issue persists after regenerating a new sync token and updating the kobo with it.

Here are the current logs in calibreweb.log

[2023-05-06 19:02:52,004]  INFO {cps:176} Starting Calibre Web...
[2023-05-06 19:02:52,213]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2023-05-06 19:02:52,630]  INFO {apscheduler.scheduler:171} Scheduler started
[2023-05-06 19:02:52,631]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/apscheduler/util.py:428: PytzUsageWarning: The localize method is no longer necessary, as this time zone supports the fold attribute (PEP 495). For more details on migrating to a PEP 495-compliant implementation, see https://pytz-deprecation-shim.readthedocs.io/en/latest/migration.html
  return tzinfo.localize(dt)

[2023-05-06 19:02:52,631]  INFO {apscheduler.scheduler:885} Added job "end scheduled task" to job store "default"
[2023-05-06 19:02:53,496]  INFO {cps.server:207} Starting Gevent server on [::]:8083
[2023-05-06 19:10:34,989]  INFO {cps.server:284} webserver stop (restart=True)
[2023-05-06 19:10:34,990]  INFO {apscheduler.scheduler:202} Scheduler has been shut down
[2023-05-06 19:10:34,994]  INFO {cps.server:265} Performing restart of Calibre-Web
[2023-05-06 19:10:35,852]  INFO {cps:176} Starting Calibre Web...
[2023-05-06 19:10:36,004] DEBUG {cps.services:49} Cannot import gmail, sending books via Gmail Oauth2 Verification will not work: No module named 'google_auth_oauthlib'
[2023-05-06 19:10:36,029]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2023-05-06 19:10:36,133] DEBUG {cps.gdriveutils:81} Cannot import pydrive, httplib2, using gdrive will not work: No module named 'pydrive'
[2023-05-06 19:10:36,426]  INFO {apscheduler.scheduler:171} Scheduler started
[2023-05-06 19:10:36,427]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/apscheduler/util.py:428: PytzUsageWarning: The localize method is no longer necessary, as this time zone supports the fold attribute (PEP 495). For more details on migrating to a PEP 495-compliant implementation, see https://pytz-deprecation-shim.readthedocs.io/en/latest/migration.html
  return tzinfo.localize(dt)

[2023-05-06 19:10:36,427]  INFO {apscheduler.scheduler:885} Added job "end scheduled task" to job store "default"
[2023-05-06 19:10:36,655] DEBUG {cps.admin:80} Cannot import Flask-Dance, login with Oauth will not work: No module named 'flask_dance'
[2023-05-06 19:10:36,660] DEBUG {cps.gdrive:44} Cannot import googleapiclient, using GDrive will not work: No module named 'googleapiclient'
[2023-05-06 19:10:37,186]  INFO {cps.server:207} Starting Gevent server on [::]:8083
[2023-05-06 19:11:00,925] DEBUG {cps.config_sql:373} _ConfigSQL updating storage
[2023-05-06 19:11:00,945] DEBUG {cps.config_sql:373} _ConfigSQL updating storage
[2023-05-06 19:11:00,945]  INFO {cps.server:284} webserver stop (restart=True)
[2023-05-06 19:11:00,946]  INFO {apscheduler.scheduler:202} Scheduler has been shut down
[2023-05-06 19:11:00,950]  INFO {cps.server:265} Performing restart of Calibre-Web
[2023-05-06 19:11:01,757]  INFO {cps:176} Starting Calibre Web...
[2023-05-06 19:11:01,914] DEBUG {cps.services:49} Cannot import gmail, sending books via Gmail Oauth2 Verification will not work: No module named 'google_auth_oauthlib'
[2023-05-06 19:11:01,936]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/flask_limiter/extension.py:293: UserWarning: Using the in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.readthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2023-05-06 19:11:02,027] DEBUG {cps.gdriveutils:81} Cannot import pydrive, httplib2, using gdrive will not work: No module named 'pydrive'
[2023-05-06 19:11:02,309]  INFO {apscheduler.scheduler:171} Scheduler started
[2023-05-06 19:11:02,310]  WARN {py.warnings:109} /var/www/calibreweb/venv/lib/python3.9/site-packages/apscheduler/util.py:428: PytzUsageWarning: The localize method is no longer necessary, as this time zone supports the fold attribute (PEP 495). For more details on migrating to a PEP 495-compliant implementation, see https://pytz-deprecation-shim.readthedocs.io/en/latest/migration.html
  return tzinfo.localize(dt)

[2023-05-06 19:11:02,311]  INFO {apscheduler.scheduler:885} Added job "end scheduled task" to job store "default"
[2023-05-06 19:11:02,573] DEBUG {cps.admin:80} Cannot import Flask-Dance, login with Oauth will not work: No module named 'flask_dance'
[2023-05-06 19:11:02,580] DEBUG {cps.gdrive:44} Cannot import googleapiclient, using GDrive will not work: No module named 'googleapiclient'
[2023-05-06 19:11:03,126]  INFO {cps.server:207} Starting Gevent server on [::]:8083
[2023-05-06 19:13:37,153] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-06 19:16:05,408] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-06 19:16:09,191]  INFO {cps.ub:898} 0 sync entries deleted
[2023-05-06 19:16:40,460]  INFO {cps.ub:898} 0 sync entries deleted

Later logs since last post do not seem to show anything very useful:

[2023-05-07 04:10:00,102]  INFO {apscheduler.executors.default:123} Running job "end scheduled task (trigger: cron[hour='4', minute='10'], next run at: 2023-05-08 04:10:00 IST)" (scheduled at 2023-05-07 04:10:00+01:00)
[2023-05-07 04:10:00,129]  INFO {apscheduler.executors.default:144} Job "end scheduled task (trigger: cron[hour='4', minute='10'], next run at: 2023-05-08 04:10:00 IST)" executed successfully
[2023-05-07 08:31:24,911] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-07 08:32:34,505]  INFO {cps.shelf:336} Shelf Kobo created
[2023-05-07 08:32:38,382]  INFO {cps.shelf:336} Shelf Kobo changed
[2023-05-07 08:32:47,672] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-07 08:32:59,199]  INFO {cps.ub:898} 0 sync entries deleted
[2023-05-07 08:33:17,295]  INFO {cps.shelf:336} Shelf Kobo changed
[2023-05-07 08:33:43,636] DEBUG {cps.web:1472} Profile updated
[2023-05-07 08:33:52,432] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-08 04:10:00,079]  INFO {apscheduler.executors.default:123} Running job "end scheduled task (trigger: cron[hour='4', minute='10'], next run at: 2023-05-09 04:10:00 IST)" (scheduled at 2023-05-08 04:10:00+01:00)
[2023-05-08 04:10:00,080]  INFO {apscheduler.executors.default:144} Job "end scheduled task (trigger: cron[hour='4', minute='10'], next run at: 2023-05-09 04:10:00 IST)" executed successfully
[2023-05-08 10:04:21,408] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}
[2023-05-08 10:06:05,861]  INFO {cps.shelf:336} Shelf Kobo changed
[2023-05-08 10:06:47,548] DEBUG {cps.updater:329} Stable version: {'version': '0.6.20'}

YunoHost-Apps / calibreweb_ynh

Kobo Sync fails #124