From 4e3a5ca33bf499a41a2f413e7751ed5d0308f0fd Mon Sep 17 00:00:00 2001 From: Ozzie Isaacs Date: Sun, 25 Apr 2021 11:20:21 +0200 Subject: [PATCH] Added additional debug messages, catch additional errors in updater --- cps/admin.py | 33 ++++++++++++++++++++------- cps/helper.py | 3 ++- cps/logger.py | 4 ++-- cps/shelf.py | 29 +++++++++++++++++------- cps/updater.py | 60 ++++++++++++++++++++++++++++++++------------------ 5 files changed, 88 insertions(+), 41 deletions(-) diff --git a/cps/admin.py b/cps/admin.py index ba82d2c2..55ab41ad 100644 --- a/cps/admin.py +++ b/cps/admin.py @@ -318,11 +318,14 @@ def delete_user(): message = _delete_user(user) count += 1 except Exception as ex: + log.error(ex) errors.append({'type': "danger", 'message': str(ex)}) if count == 1: + log.info("User {} deleted".format(user_ids)) success = [{'type': "success", 'message': message}] elif count > 1: + log.info("Users {} deleted".format(user_ids)) success = [{'type': "success", 'message': _("{} users deleted successfully").format(count)}] success.extend(errors) return Response(json.dumps(success), mimetype='application/json') @@ -472,6 +475,7 @@ def update_view_configuration(): config.save() flash(_(u"Calibre-Web configuration updated"), category="success") + log.debug("Calibre-Web configuration updated") before_request() return view_configuration() @@ -900,6 +904,7 @@ def pathchooser(): def basic_configuration(): logout_user() if request.method == "POST": + log.debug("Basic Configuration send") return _configuration_update_helper(configured=filepicker) return _configuration_result(configured=filepicker) @@ -1155,7 +1160,8 @@ def _configuration_update_helper(configured): return _configuration_result(unrar_status, gdrive_error, configured) except (OperationalError, InvalidRequestError): ub.session.rollback() - _configuration_result(_(u"Settings DB is not Writeable"), gdrive_error, configured) + log.error("Settings DB is not Writeable") + _configuration_result(_("Settings DB is not Writeable"), gdrive_error, configured) try: metadata_db = os.path.join(config.config_calibre_dir, "metadata.db") @@ -1187,6 +1193,7 @@ def _configuration_result(error_flash=None, gdrive_error=None, configured=True): if gdrive_error is None: gdrive_error = gdriveutils.get_error_text() if gdrive_error: + log.error(gdrive_error) gdrive_error = _(gdrive_error) else: # if config.config_use_google_drive and\ @@ -1196,6 +1203,7 @@ def _configuration_result(error_flash=None, gdrive_error=None, configured=True): show_back_button = current_user.is_authenticated show_login_button = config.db_configured and not current_user.is_authenticated if error_flash: + log.error(error_flash) config.load() flash(error_flash, category="error") show_login_button = False @@ -1248,13 +1256,16 @@ def _handle_new_user(to_save, content, languages, translations, kobo_support): ub.session.add(content) ub.session.commit() flash(_(u"User '%(user)s' created", user=content.name), category="success") + log.debug("User {} created".format(content.name)) return redirect(url_for('admin.admin')) except IntegrityError: ub.session.rollback() - flash(_(u"Found an existing account for this e-mail address or name."), category="error") + log.error("Found an existing account for {} or {}".format(content.name, content.email)) + flash(_("Found an existing account for this e-mail address or name."), category="error") except OperationalError: ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") def _delete_user(content): if ub.session.query(ub.User).filter(ub.User.role.op('&')(constants.ROLE_ADMIN) == constants.ROLE_ADMIN, @@ -1277,12 +1288,14 @@ def _handle_edit_user(to_save, content, languages, translations, kobo_support): try: flash(_delete_user(content), category="success") except Exception as ex: + log.error(ex) flash(str(ex), category="error") return redirect(url_for('admin.admin')) else: if not ub.session.query(ub.User).filter(ub.User.role.op('&')(constants.ROLE_ADMIN) == constants.ROLE_ADMIN, ub.User.id != content.id).count() and 'admin_role' not in to_save: - flash(_(u"No admin user remaining, can't remove admin role", nick=content.name), category="error") + log.warning("No admin user remaining, can't remove admin role from {}".format(content.name)) + flash(_("No admin user remaining, can't remove admin role"), category="error") return redirect(url_for('admin.admin')) if to_save.get("password"): content.password = generate_password_hash(to_save["password"]) @@ -1322,6 +1335,7 @@ def _handle_edit_user(to_save, content, languages, translations, kobo_support): if to_save.get("kindle_mail") != content.kindle_mail: content.kindle_mail = valid_email(to_save["kindle_mail"]) if to_save["kindle_mail"] else "" except Exception as ex: + log.error(ex) flash(str(ex), category="error") return render_title_template("user_edit.html", translations=translations, @@ -1336,12 +1350,14 @@ def _handle_edit_user(to_save, content, languages, translations, kobo_support): try: ub.session_commit() flash(_(u"User '%(nick)s' updated", nick=content.name), category="success") - except IntegrityError: + except IntegrityError as ex: ub.session.rollback() - flash(_(u"An unknown error occured."), category="error") + log.error("An unknown error occurred while changing user: {}".format(str(ex))) + flash(_(u"An unknown error occurred."), category="error") except OperationalError: ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") return "" @@ -1406,7 +1422,8 @@ def update_mailsettings(): config.save() except (OperationalError, InvalidRequestError): ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") return edit_mailsettings() if to_save.get("test"): diff --git a/cps/helper.py b/cps/helper.py index 29163685..8495687c 100644 --- a/cps/helper.py +++ b/cps/helper.py @@ -693,6 +693,7 @@ def do_download_file(book, book_format, client, data, headers): # ToDo Check headers parameter for element in headers: response.headers[element[0]] = element[1] + log.info('Downloading file: {}'.format(os.path.join(filename, data.name + "." + book_format))) return response ################################## @@ -732,7 +733,6 @@ def json_serial(obj): 'seconds': obj.seconds, 'microseconds': obj.microseconds, } - # return obj.isoformat() raise TypeError("Type %s not serializable" % type(obj)) @@ -830,6 +830,7 @@ def get_download_link(book_id, book_format, client): if book: data1 = calibre_db.get_book_format(book.id, book_format.upper()) else: + log.error("Book id {} not found for downloading".format(book_id)) abort(404) if data1: # collect downloaded books only for registered user and not for anonymous user diff --git a/cps/logger.py b/cps/logger.py index cd38e3d3..e2747f53 100644 --- a/cps/logger.py +++ b/cps/logger.py @@ -153,11 +153,11 @@ def setup(log_file, log_level=None): file_handler.baseFilename = log_file else: try: - file_handler = RotatingFileHandler(log_file, maxBytes=50000, backupCount=2, encoding='utf-8') + file_handler = RotatingFileHandler(log_file, maxBytes=100000, backupCount=2, encoding='utf-8') except IOError: if log_file == DEFAULT_LOG_FILE: raise - file_handler = RotatingFileHandler(DEFAULT_LOG_FILE, maxBytes=50000, backupCount=2, encoding='utf-8') + file_handler = RotatingFileHandler(DEFAULT_LOG_FILE, maxBytes=100000, backupCount=2, encoding='utf-8') log_file = "" file_handler.setFormatter(FORMATTER) diff --git a/cps/shelf.py b/cps/shelf.py index 68e8331b..a58e6d5c 100644 --- a/cps/shelf.py +++ b/cps/shelf.py @@ -99,12 +99,14 @@ def add_to_shelf(shelf_id, book_id): ub.session.commit() except (OperationalError, InvalidRequestError): ub.session.rollback() + log.error("Settings DB is not Writeable") flash(_(u"Settings DB is not Writeable"), category="error") if "HTTP_REFERER" in request.environ: return redirect(request.environ["HTTP_REFERER"]) else: return redirect(url_for('web.index')) if not xhr: + log.debug("Book has been added to shelf: {}".format(shelf.name)) flash(_(u"Book has been added to shelf: %(sname)s", sname=shelf.name), category="success") if "HTTP_REFERER" in request.environ: return redirect(request.environ["HTTP_REFERER"]) @@ -123,6 +125,7 @@ def search_to_shelf(shelf_id): return redirect(url_for('web.index')) if not check_shelf_edit_permissions(shelf): + log.warning("You are not allowed to add a book to the the shelf: {}".format(shelf.name)) flash(_(u"You are not allowed to add a book to the the shelf: %(name)s", name=shelf.name), category="error") return redirect(url_for('web.index')) @@ -140,7 +143,7 @@ def search_to_shelf(shelf_id): books_for_shelf = ub.searched_ids[current_user.id] if not books_for_shelf: - log.error("Books are already part of %s", shelf.name) + log.error("Books are already part of {}".format(shelf.name)) flash(_(u"Books are already part of the shelf: %(name)s", name=shelf.name), category="error") return redirect(url_for('web.index')) @@ -156,8 +159,10 @@ def search_to_shelf(shelf_id): flash(_(u"Books have been added to shelf: %(sname)s", sname=shelf.name), category="success") except (OperationalError, InvalidRequestError): ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") else: + log.error("Could not add books to shelf: {}".format(shelf.name)) flash(_(u"Could not add books to shelf: %(sname)s", sname=shelf.name), category="error") return redirect(url_for('web.index')) @@ -168,7 +173,7 @@ def remove_from_shelf(shelf_id, book_id): xhr = request.headers.get('X-Requested-With') == 'XMLHttpRequest' shelf = ub.session.query(ub.Shelf).filter(ub.Shelf.id == shelf_id).first() if shelf is None: - log.error("Invalid shelf specified: %s", shelf_id) + log.error("Invalid shelf specified: {}".format(shelf_id)) if not xhr: return redirect(url_for('web.index')) return "Invalid shelf specified", 400 @@ -197,7 +202,8 @@ def remove_from_shelf(shelf_id, book_id): ub.session.commit() except (OperationalError, InvalidRequestError): ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") if "HTTP_REFERER" in request.environ: return redirect(request.environ["HTTP_REFERER"]) else: @@ -211,6 +217,7 @@ def remove_from_shelf(shelf_id, book_id): return "", 204 else: if not xhr: + log.warning("You are not allowed to remove a book from shelf: {}".format(shelf.name)) flash(_(u"Sorry you are not allowed to remove a book from this shelf: %(sname)s", sname=shelf.name), category="error") return redirect(url_for('web.index')) @@ -258,7 +265,8 @@ def create_edit_shelf(shelf, title, page, shelf_id=False): except (OperationalError, InvalidRequestError) as ex: ub.session.rollback() log.debug_or_exception(ex) - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") except Exception as ex: ub.session.rollback() log.debug_or_exception(ex) @@ -278,6 +286,7 @@ def check_shelf_is_unique(shelf, to_save, shelf_id=False): .first() is None if not is_shelf_name_unique: + log.error("A public shelf with the name '{}' already exists.".format(to_save["title"])) flash(_(u"A public shelf with the name '%(title)s' already exists.", title=to_save["title"]), category="error") else: @@ -288,6 +297,7 @@ def check_shelf_is_unique(shelf, to_save, shelf_id=False): .first() is None if not is_shelf_name_unique: + log.error("A private shelf with the name '{}' already exists.".format(to_save["title"])) flash(_(u"A private shelf with the name '%(title)s' already exists.", title=to_save["title"]), category="error") return is_shelf_name_unique @@ -311,7 +321,8 @@ def delete_shelf(shelf_id): delete_shelf_helper(cur_shelf) except InvalidRequestError: ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") return redirect(url_for('web.index')) @@ -345,7 +356,8 @@ def order_shelf(shelf_id): ub.session.commit() except (OperationalError, InvalidRequestError): ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") shelf = ub.session.query(ub.Shelf).filter(ub.Shelf.id == shelf_id).first() result = list() @@ -415,7 +427,8 @@ def render_show_shelf(shelf_type, shelf_id, page_no, sort_param): ub.session.commit() except (OperationalError, InvalidRequestError): ub.session.rollback() - flash(_(u"Settings DB is not Writeable"), category="error") + log.error("Settings DB is not Writeable") + flash(_("Settings DB is not Writeable"), category="error") return render_title_template(page, entries=result, diff --git a/cps/updater.py b/cps/updater.py index 87aa842b..fb5219b6 100644 --- a/cps/updater.py +++ b/cps/updater.py @@ -103,20 +103,21 @@ class Updater(threading.Thread): time.sleep(2) return True except requests.exceptions.HTTPError as ex: - log.info(u'HTTP Error %s', ex) + log.error(u'HTTP Error %s', ex) self.status = 8 except requests.exceptions.ConnectionError: - log.info(u'Connection error') + log.error(u'Connection error') self.status = 9 except requests.exceptions.Timeout: - log.info(u'Timeout while establishing connection') + log.error(u'Timeout while establishing connection') self.status = 10 except (requests.exceptions.RequestException, zipfile.BadZipFile): self.status = 11 - log.info(u'General error') - except (IOError, OSError): + log.error(u'General error') + except (IOError, OSError) as ex: self.status = 12 - log.info(u'Update File Could Not be Saved in Temp Dir') + log.error(u'Possible Reason for error: update file could not be saved in temp dir') + log.debug_or_exception(ex) self.pause() return False @@ -182,39 +183,50 @@ class Updater(threading.Thread): @classmethod def moveallfiles(cls, root_src_dir, root_dst_dir): - change_permissions = True new_permissions = os.stat(root_dst_dir) - if sys.platform == "win32" or sys.platform == "darwin": - change_permissions = False - else: - log.debug('Update on OS-System : %s', sys.platform) + log.debug('Performing Update on OS-System: %s', sys.platform) + change_permissions = (sys.platform == "win32" or sys.platform == "darwin") for src_dir, __, files in os.walk(root_src_dir): dst_dir = src_dir.replace(root_src_dir, root_dst_dir, 1) if not os.path.exists(dst_dir): - os.makedirs(dst_dir) - log.debug('Create-Dir: %s', dst_dir) + try: + os.makedirs(dst_dir) + log.debug('Create directory: {}', dst_dir) + except OSError as e: + log.error('Failed creating folder: {} with error {}'.format(dst_dir, e)) if change_permissions: - # print('Permissions: User '+str(new_permissions.st_uid)+' Group '+str(new_permissions.st_uid)) - os.chown(dst_dir, new_permissions.st_uid, new_permissions.st_gid) + try: + os.chown(dst_dir, new_permissions.st_uid, new_permissions.st_gid) + except OSError as e: + old_permissions = os.stat(dst_dir) + log.error('Failed changing permissions of %s. Before: %s:%s After %s:%s error: %s', + dst_dir, old_permissions.st_uid, old_permissions.st_gid, + new_permissions.st_uid, new_permissions.st_gid, e) for file_ in files: src_file = os.path.join(src_dir, file_) dst_file = os.path.join(dst_dir, file_) if os.path.exists(dst_file): if change_permissions: permission = os.stat(dst_file) - log.debug('Remove file before copy: %s', dst_file) - os.remove(dst_file) + try: + os.remove(dst_file) + log.debug('Remove file before copy: %s', dst_file) + except OSError as e: + log.error('Failed removing file: {} with error {}'.format(dst_file, e)) else: if change_permissions: permission = new_permissions - shutil.move(src_file, dst_dir) - log.debug('Move File %s to %s', src_file, dst_dir) + try: + shutil.move(src_file, dst_dir) + log.debug('Move File %s to %s', src_file, dst_dir) + except OSError as ex: + log.error('Failed moving file from {} to {} with error {}'.format(src_file, dst_dir, ex)) if change_permissions: try: os.chown(dst_file, permission.st_uid, permission.st_gid) except OSError as e: old_permissions = os.stat(dst_file) - log.debug('Fail change permissions of %s. Before: %s:%s After %s:%s error: %s', + log.error('Failed changing permissions of %s. Before: %s:%s After %s:%s error: %s', dst_file, old_permissions.st_uid, old_permissions.st_gid, permission.st_uid, permission.st_gid, e) return @@ -266,9 +278,8 @@ class Updater(threading.Thread): shutil.rmtree(item_path, ignore_errors=True) else: try: - log.debug("Delete file %s", item_path) - # log_from_thread("Delete file " + item_path) os.remove(item_path) + log.debug("Delete file %s", item_path) except OSError: log.debug("Could not remove: %s", item_path) shutil.rmtree(source, ignore_errors=True) @@ -283,11 +294,13 @@ class Updater(threading.Thread): @classmethod def _nightly_version_info(cls): if is_sha1(constants.NIGHTLY_VERSION[0]) and len(constants.NIGHTLY_VERSION[1]) > 0: + log.debug("Nightly version: {}, {}".format(constants.NIGHTLY_VERSION[0], constants.NIGHTLY_VERSION[1])) return {'version': constants.NIGHTLY_VERSION[0], 'datetime': constants.NIGHTLY_VERSION[1]} return False @classmethod def _stable_version_info(cls): + log.debug("Stable version: {}".format(constants.STABLE_VERSION)) return constants.STABLE_VERSION # Current version @staticmethod @@ -381,6 +394,7 @@ class Updater(threading.Thread): # if 'committer' in update_data and 'message' in update_data: try: + log.debug("A new update is available.") status['success'] = True status['message'] = _( u'A new update is available. Click on the button below to update to the latest version.') @@ -401,6 +415,7 @@ class Updater(threading.Thread): except (IndexError, KeyError): status['success'] = False status['message'] = _(u'Could not fetch update information') + log.error("Could not fetch update information") return json.dumps(status) return '' @@ -468,6 +483,7 @@ class Updater(threading.Thread): # we are already on newest version, no update available if 'tag_name' not in commit[0]: status['message'] = _(u'Unexpected data while reading update information') + log.error("Unexpected data while reading update information") return json.dumps(status) if commit[0]['tag_name'] == version: status.update({