From 7aef00e66a637443b554fa4aa4ef770dcc8a005b Mon Sep 17 00:00:00 2001 From: benya Date: Sat, 18 Apr 2026 23:16:35 +0300 Subject: [PATCH] Improve GUI action logging --- PKGBUILD | 2 +- whipper/gui.py | 123 +++++++++++++++++++++++++++++++++------ whipper/test/test_gui.py | 1 + 3 files changed, 107 insertions(+), 19 deletions(-) diff --git a/PKGBUILD b/PKGBUILD index 2c42c7b..7c48901 100644 --- a/PKGBUILD +++ b/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') diff --git a/whipper/gui.py b/whipper/gui.py index f3af4a3..48b9fb9 100644 --- a/whipper/gui.py +++ b/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() diff --git a/whipper/test/test_gui.py b/whipper/test/test_gui.py index 4c140d9..ce675fd 100644 --- a/whipper/test/test_gui.py +++ b/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",