[BUGFIX] Fix makemkv job progress (#1736)

* Fix makemkv progress log path (Fixed the duplication in the log path on line 115 (Fixes #1734)
Fix makemkv stage text (Updated the progress reading logic to properly find the last PRGV and PRGC lines)
Add ETA and Track counter for makemkv (Created a text file where each job saves a timestamp when the track rip begins and use the percent complete to provide an ETA)

* Bump version from 2.23.1 to 2.23.3

---------

Co-authored-by: Mtech <62650032+microtechno9000@users.noreply.github.com>

VERSION

@@ -1 +1 @@
-2.23.2
+2.23.3

arm/ripper/makemkv.py

@@ -16,7 +16,7 @@ import os
 import shlex
 import shutil
 import subprocess
-from time import sleep
+from time import sleep, time
 
 import arm.config.config as cfg
 from arm.models import SystemDrives, Track
@@ -798,9 +798,9 @@ def process_single_tracks(job, rawpath, mode: str):
         mode: drive mode (auto or manual)
     """
     # process one track at a time based on track length
-    for track in job.tracks:
+    if mode == 'auto':
         # Process single track automatically based on start and finish times
-        if mode == 'auto':
+        for track in job.tracks:
             if track.length < int(job.config.MINLENGTH):
                 # too short
                 logging.info(f"Track #{track.track_number} of {job.no_of_titles}. Length ({track.length}) "
@@ -817,26 +817,42 @@ def process_single_tracks(job, rawpath, mode: str):
                 # track is just right
                 track.process = True
 
-        # Rip the track if the user has set it to rip, or in auto mode and the time is good
-        if track.process:
-            logging.info(f"Processing track #{track.track_number} of {(job.no_of_titles - 1)}. "
-                         f"Length is {track.length} seconds.")
-            filepathname = os.path.join(rawpath, track.filename)
-            logging.info(f"Ripping title {track.track_number} to {shlex.quote(filepathname)}")
+    # Rip the track if the user has set it to rip, or in auto mode and the time is good
 
-            cmd = [
-                "mkv",
-            ]
-            cmd += shlex.split(job.config.MKV_ARGS)
-            cmd += [
-                f"--minlength={job.config.MINLENGTH}",
-                f"--progress={progress_log(job)}",
-                f"dev:{job.devpath}",
-                track.track_number,
-                rawpath,
-            ]
-            logging.debug("Starting to rip single track.")
-            collections.deque(run(cmd, OutputType.MSG), maxlen=0)
+    tracks_to_process = [track for track in job.tracks if track.process]
+    process_index = 1
+    for track in tracks_to_process:
+        logging.info(f"Processing track #{process_index} of {len(tracks_to_process)}. "
+                     f"Length is {track.length} seconds.")
+        filepathname = os.path.join(rawpath, track.filename)
+        logging.info(f"Ripping title {track.track_number} to {shlex.quote(filepathname)}")
+        logfile_base = progress_log(job)
+        cmd = [
+            "mkv",
+        ]
+        cmd += shlex.split(job.config.MKV_ARGS)
+        cmd += [
+            f"--minlength={job.config.MINLENGTH}",
+            f"--progress={logfile_base}",
+            f"dev:{job.devpath}",
+            track.track_number,
+            rawpath,
+        ]
+        # Create a batch info file so the web gui can know when this process started, which track, and how many tracks
+        logging.debug(f"Saving batch position info for job {job.job_id}: "
+                      f"BINF:{int(time())},{process_index},{len(tracks_to_process)},0000"
+                      )
+        batch_info_file = logfile_base+".batchinfo"
+        if not os.path.exists(batch_info_file):
+            with open(batch_info_file, 'w') as f:
+                f.write(f"BINF:{int(time())},{process_index},{len(tracks_to_process)},0000")
+        else:
+            with open(batch_info_file, 'a') as f:
+                f.write(f"\nBINF:{int(time())},{process_index},{len(tracks_to_process)},0000")
+
+        logging.debug("Starting to rip single track.")
+        collections.deque(run(cmd, OutputType.MSG), maxlen=0)
+        process_index += 1
 
 
 def setup_rawpath(job, raw_path):

arm/ui/json_api.py

@@ -11,6 +11,7 @@ from pathlib import Path
 import datetime
 import psutil
 from flask import request
+from time import time, strftime, gmtime
 
 import arm.config.config as cfg
 from arm.models.config import Config
@@ -105,6 +106,22 @@ def percentage(part, whole):
     return percent
 
 
+def find_last_regex_match(pattern, iterable):
+    """
+    Find the last matching regex pattern in a given iterable
+    """
+    regex = re.compile(pattern)
+    if isinstance(iterable, (list, tuple, str)):
+        reversed_iterable = reversed(iterable)
+    else:
+        reversed_iterable = reversed(list(iterable))
+    for item in reversed_iterable:
+        retval = regex.search(item)
+        if retval:
+            return retval
+    return None
+
+
 def process_makemkv_logfile(job, job_results):
     """
     Process the logfile and find current status and job progress percent\n
@@ -112,11 +129,14 @@ def process_makemkv_logfile(job, job_results):
     """
     job_progress_status = None
     job_stage_index = None
-    lines = read_log_line(os.path.join(cfg.arm_config['LOGPATH'], job.logfile))
+    batch_log_path = os.path.join(cfg.arm_config['LOGPATH'], 'progress', str(job.job_id)) + '.log.batchinfo'
+    lines = read_log_line(os.path.join(cfg.arm_config['LOGPATH'], 'progress', str(job.job_id)) + '.log')
+    batch_index = read_log_line(batch_log_path)
     # Correctly get last entry for progress bar
-    for line in lines:
-        job_progress_status = re.search(r"PRGV:(\d{3,}),(\d+),(\d{3,})", str(line))
-        job_stage_index = re.search(r"PRGC:\d+,(\d+),\"([\w -]{2,})\"", str(line))
+
+    job_progress_status = find_last_regex_match(r"PRGV:(\d{3,}),(\d+),(\d{3,})", lines)
+    job_stage_index = find_last_regex_match(r"PRGC:(\d+),(\d+),\"([\w -]{2,})\"", lines)
+    job_batch_info = find_last_regex_match(r"BINF:(\d{10}),(\d+),(\d+),(\d+)", batch_index)
 
     if job_progress_status is not None:
         app.logger.debug(f"job_progress_status: {job_progress_status}")
@@ -124,20 +144,44 @@ def process_makemkv_logfile(job, job_results):
             f"{percentage(job_progress_status.group(1), job_progress_status.group(3)):.2f}"
         job.progress_round = percentage(job_progress_status.group(1),
                                         job_progress_status.group(3))
+        job_start_time = int(job_batch_info.group(1))
+        current_time = int(time())
+        elapsed_time = current_time - job_start_time
+        total_time = int((elapsed_time * 100) / float(job.progress))
+        time_remaining = total_time - elapsed_time
+        app.logger.debug(f"ETA values for job {job.job_id}: Elapsed seconds: {elapsed_time}, "
+                         f"Percent: {job.progress}, "
+                         f"Projected time: {total_time}, "
+                         f"Time remaining: {time_remaining}"
+                         )
+        job.eta = strftime("%Hh%Mm%Ss", gmtime(time_remaining))
     else:
         app.logger.debug(f"Job [{job.job_id}] MakeMKV status not defined - setting progress to 0%")
         job.progress = job.progress_round = job_results['progress'] = 0
+        job.eta = "Unknown"
 
     if job_stage_index is not None:
         try:
-            current_index = f"{(int(job_stage_index.group(1)) + 1)}/{job.no_of_titles} - {job_stage_index.group(2)}"
+            if job_batch_info.group(4) != job_stage_index.group(1):
+                app.logger.debug(f"Appending new batch position info for job {job.job_id}: "
+                                 f"BINF:{int(time())},"
+                                 f"{job_batch_info.group(2)},"
+                                 f"{job_batch_info.group(3)},"
+                                 f"{job_stage_index.group(1)}"
+                                 )
+                with open(batch_log_path, 'a') as f:
+                    f.write(f"\nBINF:{int(time())},"
+                            f"{job_batch_info.group(2)},"
+                            f"{job_batch_info.group(3)},"
+                            f"{job_stage_index.group(1)}"
+                            )
+            app.logger.debug(f"job_stage_index: {job_stage_index}")
+            current_index = f"Track {job_batch_info.group(2)}/{job_batch_info.group(3)}<br>{job_stage_index.group(3)}"
             job.stage = job_results['stage'] = current_index
             db.session.commit()
         except Exception as error:
             job.stage = f"Unknown -  {error}"
 
-    job.eta = "Unknown"
-
     return job_results
 
 
@@ -255,7 +299,7 @@ def read_log_line(log_file: os.PathLike):
     """
     try:
         with open(log_file, encoding="utf8", errors="ignore") as read_log_file:
-            lines = deque(read_log_file, maxlen=20)
+            lines = deque(read_log_file, maxlen=100)
     except OSError:
         app.logger.debug(f"Error while reading {log_file}, unable to calculate ETA")
         lines = ["", ""]