From b72784db7f756addc5da554762ec7a4ca4925361 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 09:57:22 -0400 Subject: [PATCH 1/8] Enhance timeout check to avoid false positives during post processing --- cps/tasks/download.py | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index 340bb886d8..3ca2b88f44 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -51,8 +51,9 @@ def run(self, worker_thread): complete_progress_cycle = 0 + last_progress_time = datetime.now() fragment_stuck_timeout = 30 # seconds - fragment_stuck_time = 0 + progress_stuck_timeout = 300 # seconds while p.poll() is None: # Check if there's data available to read @@ -71,16 +72,22 @@ def run(self, worker_thread): self.message = f"Downloading {self.media_url_link}..." self.end_time = datetime.now() self.progress = min(0.99, (complete_progress_cycle + (percentage / 100)) / 4) + last_progress_time = datetime.now() if percentage == 100: complete_progress_cycle += 1 + last_progress_time = datetime.now() if complete_progress_cycle == 4: break else: - fragment_stuck_time += 0.1 - if fragment_stuck_time >= fragment_stuck_timeout: - log.error("Download appears to be stuck.") - self.record_error_in_database("Download appears to be stuck.") - raise ValueError("Download appears to be stuck.") + elapsed_time = (datetime.now() - last_progress_time).total_seconds() + if elapsed_time >= fragment_stuck_timeout: + log.error("Download appears to be stuck at unavailable fragment.") + self.record_error_in_database("Download appears to be stuck at unavailable fragment.") + raise ValueError("Download appears to be stuck at unavailable fragment.") + if self.progress == 0.99 and elapsed_time >= progress_stuck_timeout: + log.error("Download appears to be stuck at 100%.") + self.record_error_in_database("Download appears to be stuck at 100%.") + raise ValueError("Download appears to be stuck at 100%.") sleep(0.1) From 2fdf1a07da54162c3e25ff35f7a04f06db4e5c94 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 10:02:44 -0400 Subject: [PATCH 2/8] Remove redundant logging --- cps/tasks/download.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index 3ca2b88f44..ccf19f93de 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -81,11 +81,9 @@ def run(self, worker_thread): else: elapsed_time = (datetime.now() - last_progress_time).total_seconds() if elapsed_time >= fragment_stuck_timeout: - log.error("Download appears to be stuck at unavailable fragment.") self.record_error_in_database("Download appears to be stuck at unavailable fragment.") raise ValueError("Download appears to be stuck at unavailable fragment.") if self.progress == 0.99 and elapsed_time >= progress_stuck_timeout: - log.error("Download appears to be stuck at 100%.") self.record_error_in_database("Download appears to be stuck at 100%.") raise ValueError("Download appears to be stuck at 100%.") From aab5bf72812de8cef64d41cfc1f0ec2942aefe5e Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 11:54:42 -0400 Subject: [PATCH 3/8] Strengthen timeout check by verifying file existence --- cps/tasks/download.py | 24 ++++++++++++++++++------ 1 file changed, 18 insertions(+), 6 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index ccf19f93de..44182b259c 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -52,7 +52,7 @@ def run(self, worker_thread): complete_progress_cycle = 0 last_progress_time = datetime.now() - fragment_stuck_timeout = 30 # seconds + fragment_stuck_timeout = 60 # seconds progress_stuck_timeout = 300 # seconds while p.poll() is None: @@ -80,12 +80,18 @@ def run(self, worker_thread): break else: elapsed_time = (datetime.now() - last_progress_time).total_seconds() - if elapsed_time >= fragment_stuck_timeout: - self.record_error_in_database("Download appears to be stuck at unavailable fragment.") - raise ValueError("Download appears to be stuck at unavailable fragment.") + if elapsed_time == 30: + self.message = f"Downloading {self.media_url_link}... (This is taking longer than expected)" + if self.progress < 0.99 and elapsed_time >= fragment_stuck_timeout: + if self._is_video_file_downloaded(self.media_url): + break + else: + self.record_error_in_database("Download appears to be stuck at unavailable fragment.") if self.progress == 0.99 and elapsed_time >= progress_stuck_timeout: - self.record_error_in_database("Download appears to be stuck at 100%.") - raise ValueError("Download appears to be stuck at 100%.") + if self._is_video_file_downloaded(self.media_url): + break + else: + self.record_error_in_database("Download completed but file not found.") sleep(0.1) @@ -155,6 +161,12 @@ def record_error_in_database(self, error_message): conn.execute("UPDATE media SET error = ? WHERE webpath = ?", (error_message, self.media_url)) conn.commit() conn.close() + raise ValueError(error_message) + + def _is_video_file_downloaded(self, media_url): + """Check if the video file is downloaded""" + with sqlite3.connect(XKLB_DB_FILE) as conn: + return bool(conn.execute("SELECT path FROM media WHERE webpath = ? AND path NOT LIKE 'http%'", (media_url,)).fetchone()[0]) @property def name(self): From c47d1e3ec3966ed8b2c484584d6a17053a504c03 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 13:15:31 -0400 Subject: [PATCH 4/8] Default fragment stuck timeout to 30s again Also make code more concise and reliable --- cps/tasks/download.py | 24 ++++++++---------------- 1 file changed, 8 insertions(+), 16 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index 44182b259c..f996acd055 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -52,7 +52,7 @@ def run(self, worker_thread): complete_progress_cycle = 0 last_progress_time = datetime.now() - fragment_stuck_timeout = 60 # seconds + fragment_stuck_timeout = 30 # seconds progress_stuck_timeout = 300 # seconds while p.poll() is None: @@ -72,7 +72,6 @@ def run(self, worker_thread): self.message = f"Downloading {self.media_url_link}..." self.end_time = datetime.now() self.progress = min(0.99, (complete_progress_cycle + (percentage / 100)) / 4) - last_progress_time = datetime.now() if percentage == 100: complete_progress_cycle += 1 last_progress_time = datetime.now() @@ -80,21 +79,14 @@ def run(self, worker_thread): break else: elapsed_time = (datetime.now() - last_progress_time).total_seconds() - if elapsed_time == 30: - self.message = f"Downloading {self.media_url_link}... (This is taking longer than expected)" - if self.progress < 0.99 and elapsed_time >= fragment_stuck_timeout: - if self._is_video_file_downloaded(self.media_url): - break - else: + if (self.progress < 0.99 and elapsed_time >= fragment_stuck_timeout) \ + or (self.progress == 0.99 and elapsed_time >= progress_stuck_timeout): + if not self._is_video_file_downloaded(self.media_url): self.record_error_in_database("Download appears to be stuck at unavailable fragment.") - if self.progress == 0.99 and elapsed_time >= progress_stuck_timeout: - if self._is_video_file_downloaded(self.media_url): - break - else: - self.record_error_in_database("Download completed but file not found.") + self.message = f"Downloading {self.media_url_link}... (This is taking longer than expected)" sleep(0.1) - + p.wait() # Database operations @@ -129,7 +121,7 @@ def run(self, worker_thread): else: log.error("Failed to send the requested file to %s", self.original_url) self.message = f"{self.media_url_link} failed to download: {response.status_code} {response.reason}" - + conn.close() except Exception as e: @@ -143,7 +135,7 @@ def run(self, worker_thread): self.stat = STAT_FINISH_SUCCESS log.info("Download task for %s completed successfully", self.media_url) else: - self.end_time = datetime.now() + self.end_time = datetime.now() self.stat = STAT_FAIL else: From c337940700ed3ab0ae8489b2c45cba81bba269f2 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 16:11:09 -0400 Subject: [PATCH 5/8] Remove fail upon timeout reach This goes on par with xklb execution. Fails only when xklb fails --- cps/tasks/download.py | 22 +++++----------------- 1 file changed, 5 insertions(+), 17 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index f996acd055..1ab51b4fb5 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -6,9 +6,9 @@ from datetime import datetime from flask_babel import lazy_gettext as N_, gettext as _ -from cps.constants import XKLB_DB_FILE -from cps.services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING -from cps.subproc_wrapper import process_open +from ..constants import XKLB_DB_FILE +from ..services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING +from ..subproc_wrapper import process_open from .. import logger from time import sleep @@ -53,7 +53,6 @@ def run(self, worker_thread): last_progress_time = datetime.now() fragment_stuck_timeout = 30 # seconds - progress_stuck_timeout = 300 # seconds while p.poll() is None: # Check if there's data available to read @@ -61,7 +60,7 @@ def run(self, worker_thread): if rlist: line = p.stdout.readline() if line: - if re.search(pattern_success, line): + if re.search(pattern_success, line) or complete_progress_cycle == 4: # 2024-01-10: 99% (a bit arbitrary) is explained here... # https://github.com/iiab/calibre-web/pull/88#issuecomment-1885916421 self.progress = 0.99 @@ -75,14 +74,9 @@ def run(self, worker_thread): if percentage == 100: complete_progress_cycle += 1 last_progress_time = datetime.now() - if complete_progress_cycle == 4: - break else: elapsed_time = (datetime.now() - last_progress_time).total_seconds() - if (self.progress < 0.99 and elapsed_time >= fragment_stuck_timeout) \ - or (self.progress == 0.99 and elapsed_time >= progress_stuck_timeout): - if not self._is_video_file_downloaded(self.media_url): - self.record_error_in_database("Download appears to be stuck at unavailable fragment.") + if elapsed_time >= fragment_stuck_timeout: self.message = f"Downloading {self.media_url_link}... (This is taking longer than expected)" sleep(0.1) @@ -153,12 +147,6 @@ def record_error_in_database(self, error_message): conn.execute("UPDATE media SET error = ? WHERE webpath = ?", (error_message, self.media_url)) conn.commit() conn.close() - raise ValueError(error_message) - - def _is_video_file_downloaded(self, media_url): - """Check if the video file is downloaded""" - with sqlite3.connect(XKLB_DB_FILE) as conn: - return bool(conn.execute("SELECT path FROM media WHERE webpath = ? AND path NOT LIKE 'http%'", (media_url,)).fetchone()[0]) @property def name(self): From c934f202dcf7da32684f0f37e920bd42fda8f59f Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 16:55:57 -0400 Subject: [PATCH 6/8] Use absolute imports Co-authored-by: Bernie Innocenti --- cps/tasks/download.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index 1ab51b4fb5..8fe823fbfa 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -6,9 +6,9 @@ from datetime import datetime from flask_babel import lazy_gettext as N_, gettext as _ -from ..constants import XKLB_DB_FILE -from ..services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING -from ..subproc_wrapper import process_open +from calibreweb.cps.constants import XKLB_DB_FILE +from calibreweb.cps.services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING +from calibreweb.cps.subproc_wrapper import process_open from .. import logger from time import sleep From 5674e130f84bfc890a23301f06c61a5223230e26 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 17:38:20 -0400 Subject: [PATCH 7/8] Fix imports --- cps/tasks/download.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index 8fe823fbfa..ed05761ae3 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -6,9 +6,9 @@ from datetime import datetime from flask_babel import lazy_gettext as N_, gettext as _ -from calibreweb.cps.constants import XKLB_DB_FILE -from calibreweb.cps.services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING -from calibreweb.cps.subproc_wrapper import process_open +from cps.constants import XKLB_DB_FILE +from cps.services.worker import CalibreTask, STAT_FINISH_SUCCESS, STAT_FAIL, STAT_STARTED, STAT_WAITING +from cps.subproc_wrapper import process_open from .. import logger from time import sleep From de4fdceaf9ec0b91ce6afa33495f2fa93159b0c3 Mon Sep 17 00:00:00 2001 From: Blondel MONDESIR Date: Tue, 4 Jun 2024 17:41:59 -0400 Subject: [PATCH 8/8] Optimize run time --- cps/tasks/download.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/cps/tasks/download.py b/cps/tasks/download.py index ed05761ae3..a6ac3dda82 100644 --- a/cps/tasks/download.py +++ b/cps/tasks/download.py @@ -55,6 +55,7 @@ def run(self, worker_thread): fragment_stuck_timeout = 30 # seconds while p.poll() is None: + self.end_time = datetime.now() # Check if there's data available to read rlist, _, _ = select.select([p.stdout], [], [], 0.1) if rlist: @@ -69,7 +70,6 @@ def run(self, worker_thread): percentage = int(re.search(r'\d+', line).group()) if percentage < 100: self.message = f"Downloading {self.media_url_link}..." - self.end_time = datetime.now() self.progress = min(0.99, (complete_progress_cycle + (percentage / 100)) / 4) if percentage == 100: complete_progress_cycle += 1 @@ -124,12 +124,11 @@ def run(self, worker_thread): self.record_error_in_database(str(e)) finally: + self.end_time = datetime.now() if p.returncode == 0 or self.progress == 1.0: - self.end_time = datetime.now() self.stat = STAT_FINISH_SUCCESS log.info("Download task for %s completed successfully", self.media_url) else: - self.end_time = datetime.now() self.stat = STAT_FAIL else: