Improve GUI action logging

PKGBUILD

@@ -1,5 +1,5 @@
 pkgname=whipper-git
-pkgver=0.10.0.r66.g992923b
+pkgver=0.10.2.r0.g9564c7c
 pkgrel=1
 pkgdesc='CD-DA ripper prioritising accuracy over speed'
 arch=('x86_64')

whipper/gui.py

@@ -434,6 +434,14 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
         end_iter = self.log_buffer.get_end_iter()
         self.log_buffer.insert(end_iter, text)
 
+    def _log_action(self, message, *args, level=logging.INFO):
+        if args:
+            message = message % args
+        logger.log(level, message)
+        if not message.endswith("\n"):
+            message += "\n"
+        self._append_log(message)
+
     def _clear_log(self):
         self.log_buffer.set_text("")
 
@@ -563,6 +571,7 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
         current = self.device_combo.get_active_text()
         self.device_combo.remove_all()
         devices = drive.getAllDevicePaths()
+        logger.info("refreshing optical drives")
         for path in devices:
             self.device_combo.append_text(path)
         if not devices:
@@ -570,12 +579,15 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             self.device_combo.set_active(0)
             self.read_button.set_sensitive(False)
             self.rip_button.set_sensitive(False)
+            logger.warning("no optical drives detected")
         else:
             self.read_button.set_sensitive(True)
             if current in devices:
                 self.device_combo.set_active(devices.index(current))
             else:
                 self.device_combo.set_active(0)
+            logger.info("detected %d optical drive(s); active device: %s",
+                        len(devices), self.device_combo.get_active_text())
             self._apply_configured_offset()
 
     def _selected_device(self):
@@ -646,31 +658,36 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             return
         info = drive.getDeviceInfo(device)
         if not info:
+            logger.info("no configured offset information for %s", device)
             return
         try:
             offset = config.Config().getReadOffset(*info)
         except KeyError:
+            logger.info("configured read offset not found for %s", device)
             return
         if offset is not None:
             self.offset_spin.set_value(int(offset))
+            logger.info("loaded configured read offset %d for %s", offset, device)
 
     def _read_disc_worker(self, device, country):
         try:
             self.scan_cancel_requested = False
             GLib.idle_add(self._clear_log)
             GLib.idle_add(self._reset_progress)
-            GLib.idle_add(self._append_log, "Reading disc from %s\n\n" % device)
+            GLib.idle_add(self._log_action, "Reading disc from %s", device)
             GLib.idle_add(self._set_running_state, True, "Reading disc")
             GLib.idle_add(self.progress_label.set_text, "Scanning disc and looking up MusicBrainz")
 
             runner = CancellableSyncRunner()
             self.scan_runner = runner
 
+            GLib.idle_add(self._log_action, "Preparing drive %s", device)
             utils.load_device(device)
             utils.unmount_device(device)
             if drive.get_cdrom_drive_status(device) == 1:
                 raise OSError("No CD detected, please insert one and retry")
 
+            GLib.idle_add(self._log_action, "Reading disc TOC")
             toc_task = cdrdao.ReadTOCTask(device, fast_toc=True)
             runner.run(toc_task, verbose=False)
             ittoc = toc_task.toc.table
@@ -681,6 +698,12 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             if self.scan_cancel_requested:
                 raise RuntimeError("Disc scan cancelled")
 
+            GLib.idle_add(
+                self._log_action,
+                "Querying MusicBrainz for %s%s",
+                mbid,
+                " (country=%s)" % country if country else "",
+            )
             try:
                 releases = mbngs.musicbrainz(mbid, country=country or None, record=False)
             except mbngs.NotFoundException:
@@ -707,12 +730,12 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
                 self._append_log("CDDB disc id: %s\n" % cddb)
                 self._append_log("MusicBrainz disc id: %s\n" % mbid)
                 self._append_log("Disc duration: %s, %s audio tracks\n" % (duration, track_count))
-                self._append_log("\nFound %d matching release(s)\n" % len(releases))
+                self._log_action("Found %d matching release(s)", len(releases))
                 self._update_release_store(releases)
                 self._set_running_state(False, "Disc ready")
                 self.progress_label.set_text("Disc metadata loaded")
                 if not releases:
-                    self._append_log("No MusicBrainz matches found\n")
+                    self._log_action("No MusicBrainz matches found", level=logging.WARNING)
                 return False
 
             GLib.idle_add(apply_results)
@@ -726,12 +749,12 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
                 self._set_label("device", device)
                 if self.scan_cancel_requested:
                     self._set_label("disc_status", "Cancelled")
-                    self._append_log("Disc scan cancelled\n")
+                    self._log_action("Disc scan cancelled", level=logging.WARNING)
                     self._set_running_state(False, "Cancelled")
                     self.progress_label.set_text("Disc scan cancelled")
                 else:
                     self._set_label("disc_status", "Error")
-                    self._append_log("%s\n" % exc)
+                    self._log_action("%s", exc, level=logging.ERROR)
                     self._set_running_state(False, "Failed")
                     self.progress_label.set_text("Disc scan failed")
                 return False
@@ -974,21 +997,40 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             GLib.idle_add(self._reset_progress)
             GLib.idle_add(self._set_running_state, True, "Ripping disc")
             GLib.idle_add(self.progress_label.set_text, "Preparing rip")
-            GLib.idle_add(self._append_log, "Starting native whipper rip\n\n")
+            GLib.idle_add(self._log_action, "Starting native whipper rip")
 
             runner = CancellableSyncRunner()
             self.rip_runner = runner
             conf = config.Config()
             program = Program(conf, record=False)
 
+            GLib.idle_add(
+                self._log_action,
+                "Rip settings: device=%s output=%s working_dir=%s logger=%s offset=%d overread=%s cover_art=%s retries=%s keep_going=%s cdr=%s unknown=%s",
+                settings["device"],
+                settings["output_directory"],
+                settings["working_directory"] or "-",
+                settings["logger"],
+                settings["offset"],
+                settings["overread"],
+                settings["cover_art"] or "disabled",
+                settings["max_retries"],
+                settings["keep_going"],
+                settings["cdr"],
+                settings["unknown"],
+            )
+
             if settings["working_directory"]:
+                GLib.idle_add(self._log_action, "Changing working directory to %s", settings["working_directory"])
                 os.chdir(os.path.expanduser(settings["working_directory"]))
 
+            GLib.idle_add(self._log_action, "Preparing drive %s", settings["device"])
             utils.load_device(settings["device"])
             utils.unmount_device(settings["device"])
             if drive.get_cdrom_drive_status(settings["device"]) == 1:
                 raise OSError("No CD detected, please insert one and retry")
 
+            GLib.idle_add(self._log_action, "Reading fast TOC")
             ittoc = program.getFastToc(runner, settings["device"])
             program.getRipResult()
             cddb = ittoc.getCDDBDiscId()
@@ -996,22 +1038,27 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             GLib.idle_add(self._append_log, "CDDB disc id: %s\n" % cddb)
             GLib.idle_add(self._append_log, "MusicBrainz disc id: %s\n" % mbdiscid)
 
+            GLib.idle_add(self._log_action, "Resolving release metadata")
             program.metadata = self._resolve_release_metadata(mbdiscid, settings)
             if program.metadata is None and not settings["unknown"]:
                 raise RuntimeError("Unable to resolve disc metadata. Select a release or enable ripping without metadata.")
             if program.metadata is not None:
                 program.metadata.discid = mbdiscid
                 GLib.idle_add(
-                    self._append_log,
+                    self._log_action,
                     "Using release: %s - %s\n" % (
                         program.metadata.artist or "Unknown Artist",
                         program.metadata.releaseTitle or program.metadata.title or "Unknown Title",
                     ),
                 )
+            else:
+                GLib.idle_add(self._log_action, "Continuing without release metadata", level=logging.WARNING)
 
             program.result.isCdr = cdrdao.DetectCdr(settings["device"])
             if program.result.isCdr and not settings["cdr"]:
                 raise RuntimeError("Inserted disc appears to be a CD-R. Enable 'Allow CD-R' to continue.")
+            if program.result.isCdr:
+                GLib.idle_add(self._log_action, "Detected CD-R media", level=logging.WARNING)
 
             out_fpath = program.getPath(
                 settings["output_directory"],
@@ -1019,6 +1066,7 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
                 mbdiscid,
                 program.metadata,
             )
+            GLib.idle_add(self._log_action, "Reading full disc table")
             itable = program.getTable(
                 runner,
                 ittoc.getCDDBDiscId(),
@@ -1045,6 +1093,15 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             program.result.overread = settings["overread"]
             program.result.logger = settings["logger"]
             program.outdir = settings["output_directory"]
+            GLib.idle_add(
+                self._log_action,
+                "Drive info: vendor=%s model=%s release=%s offset=%s overread=%s",
+                program.result.vendor,
+                program.result.model,
+                program.result.release,
+                program.result.offset,
+                program.result.overread,
+            )
 
             disc_name = program.getPath(program.outdir, settings["disc_template"], mbdiscid, program.metadata)
             dirname = os.path.dirname(disc_name)
@@ -1052,17 +1109,22 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
                 log_file = disc_name + ".log"
                 if os.path.exists(log_file):
                     raise RuntimeError("output directory %s is a finished rip" % dirname)
+                GLib.idle_add(self._log_action, "Using existing output directory %s", dirname)
             else:
                 os.makedirs(dirname)
+                GLib.idle_add(self._log_action, "Created output directory %s", dirname)
 
             cover_art_path = None
             if settings["cover_art"] in {"embed", "complete"} and importlib.util.find_spec("PIL") is None:
-                GLib.idle_add(self._append_log, "Cover art embedding requires Pillow; continuing without embedded art\n")
+                GLib.idle_add(self._log_action, "Cover art embedding requires Pillow; continuing without embedded art", level=logging.WARNING)
             elif settings["cover_art"] in {"file", "embed", "complete"}:
                 if getattr(program.metadata, "mbid", None):
+                    GLib.idle_add(self._log_action, "Fetching cover art with mode %s", settings["cover_art"])
                     cover_art_path = program.getCoverArt(dirname, program.metadata.mbid)
+                    if cover_art_path is not None:
+                        GLib.idle_add(self._log_action, "Cover art saved to %s", cover_art_path)
                 else:
-                    GLib.idle_add(self._append_log, "Cover art requested but disc metadata is unavailable\n")
+                    GLib.idle_add(self._log_action, "Cover art requested but disc metadata is unavailable", level=logging.WARNING)
             if settings["cover_art"] == "file":
                 embed_cover_art_path = None
             else:
@@ -1071,14 +1133,16 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
             skipped_tracks = []
             rip_numbers = []
             if program.getHTOA():
+                GLib.idle_add(self._log_action, "Hidden Track One Audio detected")
                 rip_numbers.append(0)
             for index, track in enumerate(itable.tracks, start=1):
                 if track.audio:
                     rip_numbers.append(index)
                 else:
-                    GLib.idle_add(self._append_log, "Skipping data track %d, not implemented\n" % index)
+                    GLib.idle_add(self._log_action, "Skipping data track %d, not implemented", index, level=logging.WARNING)
                     track.indexes[1].relative = 0
 
+            GLib.idle_add(self._log_action, "Planned rip items: %d", len(rip_numbers))
             total_items = len(rip_numbers)
             for item_index, track_number in enumerate(rip_numbers, start=1):
                 if self.rip_cancel_requested:
@@ -1098,15 +1162,19 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
 
             if settings["cover_art"] == "embed" and cover_art_path is not None:
                 os.remove(cover_art_path)
+                GLib.idle_add(self._log_action, "Removed temporary cover art file %s", cover_art_path)
 
             if self.rip_cancel_requested:
                 raise RipCancelledError("Rip cancelled")
 
             program.skipped_tracks = skipped_tracks or None
+            GLib.idle_add(self._log_action, "Writing CUE sheet")
             program.writeCue(disc_name)
+            GLib.idle_add(self._log_action, "Writing M3U playlist")
             program.write_m3u(disc_name)
 
             try:
+                GLib.idle_add(self._log_action, "Running AccurateRip image verification")
                 with contextlib.redirect_stdout(io.StringIO()) as stdout_buffer:
                     program.verifyImage(runner, itable)
                     accurip.print_report(program.result)
@@ -1114,19 +1182,20 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
                 if report_output:
                     GLib.idle_add(self._append_log, "\n" + report_output + "\n")
             except accurip.EntryNotFound:
-                GLib.idle_add(self._append_log, "AccurateRip entry not found\n")
+                GLib.idle_add(self._log_action, "AccurateRip entry not found", level=logging.WARNING)
 
             txt_logger = result.getLoggers()[settings["logger"]]()
+            GLib.idle_add(self._log_action, "Writing rip log with logger '%s'", settings["logger"])
             program.writeLog(disc_name, txt_logger)
             if skipped_tracks:
-                GLib.idle_add(self._append_log, "%d track(s) were skipped during this rip\n" % len(skipped_tracks))
+                GLib.idle_add(self._log_action, "%d track(s) were skipped during this rip", len(skipped_tracks), level=logging.WARNING)
                 GLib.idle_add(self._finish_rip, 5, "Done with skipped tracks")
             else:
-                GLib.idle_add(self._append_log, "Rip finished successfully\n")
+                GLib.idle_add(self._log_action, "Rip finished successfully")
                 GLib.idle_add(self._finish_rip, 0, "Done")
         except Exception as exc:
             if not isinstance(exc, RipCancelledError):
-                GLib.idle_add(self._append_log, "%s\n" % exc)
+                GLib.idle_add(self._log_action, "%s", exc, level=logging.ERROR)
             GLib.idle_add(self._finish_rip, 1, "Cancelled" if self.rip_cancel_requested else "Failed")
         finally:
             self.rip_runner = None
@@ -1146,6 +1215,7 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
         self.rip_button.set_sensitive(self._can_rip())
 
     def _on_refresh_clicked(self, _button):
+        self._log_action("Refreshing drive list")
         self._refresh_devices()
 
     def _on_unknown_toggled(self, _button):
@@ -1167,12 +1237,21 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
     def _on_device_changed(self, _combo):
         self._apply_configured_offset()
         self._save_gui_settings()
+        device = self._selected_device()
+        if device:
+            self._log_action("Selected device %s", device)
 
     def _on_read_clicked(self, _button):
         device = self._selected_device()
         if not device:
+            self._log_action("Read requested without an active device", level=logging.WARNING)
             return
         country = self.country_entry.get_text().strip()
+        self._log_action(
+            "Read requested for %s%s",
+            device,
+            " with country filter %s" % country if country else "",
+        )
         self.worker = threading.Thread(
             target=self._read_disc_worker,
             args=(device, country),
@@ -1182,16 +1261,24 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
 
     def _on_rip_clicked(self, _button):
         if not self._can_rip():
-            self._append_log("Select a release or enable ripping without metadata.\n")
+            self._log_action("Rip requested without a selected release", level=logging.WARNING)
             self.status_label.set_text("Missing release")
             return
         settings = self._collect_rip_settings()
         try:
             self._validate_rip_settings(settings)
         except Exception as exc:
-            self._append_log("%s\n" % exc)
+            self._log_action("%s", exc, level=logging.ERROR)
             self.status_label.set_text("Invalid settings")
             return
+        if self.current_release is not None:
+            self._log_action(
+                "Rip requested for release %s - %s",
+                self.current_release.artist or "Unknown Artist",
+                self.current_release.releaseTitle or self.current_release.title or "Unknown Title",
+            )
+        else:
+            self._log_action("Rip requested without bound metadata release", level=logging.WARNING)
         self.worker = threading.Thread(
             target=self._rip_disc_worker,
             args=(settings,),
@@ -1202,11 +1289,11 @@ class WhipperGui(Gtk.Application if Gtk is not None else object):
     def _on_stop_clicked(self, _button):
         if self.scan_runner is not None:
             self.scan_cancel_requested = True
-            self._append_log("\nStopping scan...\n")
+            self._log_action("Stopping scan", level=logging.WARNING)
             self.scan_runner.cancel()
         elif self.rip_runner is not None:
             self.rip_cancel_requested = True
-            self._append_log("\nStopping rip...\n")
+            self._log_action("Stopping rip", level=logging.WARNING)
             self.rip_runner.cancel()
 
 

whipper/test/test_gui.py

@@ -296,6 +296,7 @@ def _make_ui_app(tmp_path):
     app._config_path = lambda: tmp_path / "gui.json"
     _bind_methods(
         app,
+        "_log_action",
         "_collect_gui_settings",
         "_save_gui_settings",
         "_load_gui_settings",