From 633fbbaf9129ee73456cc7b0011ea7a8b144af34 Mon Sep 17 00:00:00 2001 From: Emma Thorpe Date: Wed, 26 Aug 2026 13:28:21 +0100 Subject: [PATCH 1/4] test: prove the database lands at the device root, not in the music folder The two tools disagree about where the root is. rsync copies artist folders into /Music, while the database builder must run one level up, where .rockbox lives, and must record /Music/... paths despite reading the bytes from the mirror. device_prefix is what reconciles them, and until now that was only argued rather than demonstrated. Unprivileged user namespaces make a real bind mount possible, so the test can create an actual mount point and exercise the derivation instead of asserting the shape of the script. A stub builder records its working directory and what it could see. The test asserts the .tcd file arrives beside .rockbox rather than inside Music, that the build ran in the scratch root and not on the card, and that it could walk into the mirror through the symlink -- which is the mechanism that produces device paths from mirror bytes. It skips where user namespaces are unavailable, which includes the CI container. --- tests/test_sync_to_ipod.py | 64 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 64 insertions(+) diff --git a/tests/test_sync_to_ipod.py b/tests/test_sync_to_ipod.py index c0b4e82..b95d392 100644 --- a/tests/test_sync_to_ipod.py +++ b/tests/test_sync_to_ipod.py @@ -271,3 +271,67 @@ def test_the_scan_reads_from_the_mirror_not_the_device(): assert 'ln -s "$mirror"' in script assert 'cd "$scratch"' in script + + +def can_bind_mount(): + """User namespaces let an unprivileged process bind mount. Not everywhere, + notably not inside some containers, so the test that needs it skips.""" + return ( + subprocess.run( + ["unshare", "-Umr", "true"], capture_output=True, check=False + ).returncode + == 0 + ) + + +@pytest.mark.skipif(not can_bind_mount(), reason="needs unprivileged user namespaces") +def test_the_database_lands_at_the_device_root_not_the_music_folder(tmp_path): + """The two tools disagree about where the root is. rsync copies artist + folders into /Music; the database tool must run one level up, where + .rockbox lives, and must record /Music/... paths while reading the bytes + from the mirror. device_prefix is what reconciles them. + """ + mirror = tmp_path / "mirror" / "Pendulum" / "Immersion" + mirror.mkdir(parents=True) + (mirror / "01.mp3").write_bytes(b"not really an mp3") + card = tmp_path / "card" + (card / ".rockbox").mkdir(parents=True) + (card / "Music").mkdir() + device = tmp_path / "device" + device.mkdir() + + tool = tmp_path / "fake-database" + # Records where it was run and what it could see, which is the whole + # question; producing a real database needs Rockbox's builder. + tool.write_text( + "#!/bin/sh\n" + "printf '%s\\n' \"$PWD\" > .rockbox/where.txt\n" + "ls Music/ > .rockbox/saw.txt\n" + "echo db > .rockbox/database_0.tcd\n" + ) + tool.chmod(0o755) + + script = ( + f"mount --bind {card} {device} && " + f"XDG_CACHE_HOME={tmp_path / 'cache'} MUSIC_MIRROR_DATABASE_TOOL={tool} " + f"bash {SCRIPT} -f -S -U -Q {tmp_path / 'mirror'} {device / 'Music'}" + ) + result = subprocess.run( + ["unshare", "-Umr", "sh", "-c", script], capture_output=True, text=True + ) + + assert result.returncode == 0, result.stderr + # The database lands beside the device root, not inside Music. + assert (card / ".rockbox" / "database_0.tcd").is_file() + # Only *.tcd is copied across, so the markers stay in the scratch root -- + # which is itself the point: nothing else is written to the device. + scratch = tmp_path / "cache" / "music-mirror" / "database" / ".rockbox" + assert not (card / ".rockbox" / "where.txt").exists() + + # It ran in the scratch root, not on the card. + where = (scratch / "where.txt").read_text().strip() + assert where.endswith("music-mirror/database"), where + # ...and could walk into the mirror through a symlink named for the device + # prefix, which is how the paths come out as /Music/... while the bytes are + # read from somewhere else entirely. + assert "Pendulum" in (scratch / "saw.txt").read_text() -- 2.54.0 From 19ac9e5d92b304d6c78553b1d3076ce45b151967 Mon Sep 17 00:00:00 2001 From: Emma Thorpe Date: Wed, 26 Aug 2026 13:57:49 +0100 Subject: [PATCH 2/4] fix: stop counting by default; the pass costs more than the transfer The counting pass was added so the progress line could show a percentage and an estimate, and on a real card it turned out to dominate the run. Measured against the device: reading a track from the SMB mirror ran at 35 MB/s and writing to the card at 21 MB/s, while the sync itself managed tens of kilobytes per second. Neither end was slow. The cost was traversing fifty thousand files across six thousand directories on FAT, and the counting pass does that a second time, comparing both trees in full exactly as the transfer does. Counting is now opt-in behind -P. Without it the progress line still shows the running count, the transfer rate and the album in flight; the percentage and the estimate are what needed the extra walk, and they were the least useful part of the display. That the fix for "it looks hung" was itself making it slow is the sort of thing only measuring catches. The line still answers the question it was added for -- whether anything is happening -- without paying for the part that merely made it prettier. --- README.md | 22 +++++++++++++++------- tests/test_sync_to_ipod.py | 23 +++++++++++++++++------ tools/sync-to-ipod.sh | 21 +++++++++++++-------- 3 files changed, 45 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 9e20d89..1f455e2 100644 --- a/README.md +++ b/README.md @@ -178,12 +178,20 @@ entirely for the first two seconds, where the window is microseconds wide and would report gigabytes per second. rsync says nothing at all while it builds its file list, which on fifty -thousand files over USB is minutes of apparent hang, and its own `progress2` -percentage is computed against a list it has not finished discovering. So the -script counts first — files and bytes both, a second pass over the tree, which -is what a percentage and an estimate that mean something cost — and renders the -rest itself. Piped to a log it prints a plain line every thirty seconds -instead, with no carriage returns, and a summary at the end either way. +thousand files is minutes of apparent hang, and its own `progress2` percentage +is computed against a list it has not finished discovering. So the script +renders its own. + +**The percentage and the estimate are opt-in, via `-P`.** They need a total, +the total needs a counting pass, and that pass walks and compares both trees in +full exactly as the transfer does. Measured on a real card: read from the +source at 35 MB/s and write to the card at 21 MB/s, yet the sync crawled — +because the traversal, not the data, was the cost, and it was being paid twice. +Without `-P` the line still shows the running count, the rate and the album in +flight; only the two figures that needed the second walk are missing. + +Piped to a log it prints a plain line every thirty seconds instead, with no +carriage returns, and a summary at the end either way. ### The Rockbox database @@ -260,7 +268,7 @@ worth doing: | ----- | --- | | Mount the source with `actimeo=60,cache=loose` | SMB defaults to a **one second** attribute cache, so nearly every `stat` goes to the wire — twice, once per pass. This is the single biggest change and it is a mount option, not an rsync flag. | | Put the card in a reader for the first load | USB 2.0 through an iPod in disk mode is the floor for the destination. No amount of source tuning gets past it. | -| `-Q` | Skips the counting pass entirely. Costs the percentage and the estimate, saves a whole walk of the tree. | +| Counting is off by default | The percentage costs a second full traversal of both trees. On a FAT card of fifty thousand files that is slower than the transfer. `-P` asks for it. | | `--whole-file`, `--omit-dir-times` | Already set. The first stops rsync checksumming destination files it is about to overwrite whole; the second drops a setattr per directory, 6,150 of them. | **NFS instead of SMB** is worth trying but is not the big win it looks like. diff --git a/tests/test_sync_to_ipod.py b/tests/test_sync_to_ipod.py index b95d392..440e48c 100644 --- a/tests/test_sync_to_ipod.py +++ b/tests/test_sync_to_ipod.py @@ -176,16 +176,16 @@ def test_the_help_says_how_to_reach_and_leave_disk_mode(): assert "holding Play" in help_text -def test_quick_mode_skips_the_counting_pass(mirror, tmp_path): - """Over SMB the walk is the expensive part, and doing it twice for a - percentage is not always the trade you want.""" +def test_counting_is_off_by_default(mirror, tmp_path): + """The counting pass walks and compares both trees exactly as the transfer + does. On a FAT card of fifty thousand files that costs more than moving the + data, so the percentage has to be asked for.""" destination = tmp_path / "dest" destination.mkdir() - result = run("-f", "-S", "-U", "-Q", str(mirror), str(destination)) + result = run("-f", "-S", "-U", str(mirror), str(destination)) assert result.returncode == 0, result.stderr - assert "skipping the count" in result.stderr assert "files to copy" not in result.stderr assert (destination / "Album" / "track.mp3").is_file() @@ -314,7 +314,7 @@ def test_the_database_lands_at_the_device_root_not_the_music_folder(tmp_path): script = ( f"mount --bind {card} {device} && " f"XDG_CACHE_HOME={tmp_path / 'cache'} MUSIC_MIRROR_DATABASE_TOOL={tool} " - f"bash {SCRIPT} -f -S -U -Q {tmp_path / 'mirror'} {device / 'Music'}" + f"bash {SCRIPT} -f -S -U {tmp_path / 'mirror'} {device / 'Music'}" ) result = subprocess.run( ["unshare", "-Umr", "sh", "-c", script], capture_output=True, text=True @@ -335,3 +335,14 @@ def test_the_database_lands_at_the_device_root_not_the_music_folder(tmp_path): # prefix, which is how the paths come out as /Music/... while the bytes are # read from somewhere else entirely. assert "Pendulum" in (scratch / "saw.txt").read_text() + + +def test_counting_can_be_asked_for(mirror, tmp_path): + """When the destination is cheap to traverse, the percentage is worth it.""" + destination = tmp_path / "dest" + destination.mkdir() + + result = run("-f", "-S", "-U", "-P", str(mirror), str(destination)) + + assert result.returncode == 0, result.stderr + assert "files to copy" in result.stderr diff --git a/tools/sync-to-ipod.sh b/tools/sync-to-ipod.sh index 9b7a0fc..206293d 100755 --- a/tools/sync-to-ipod.sh +++ b/tools/sync-to-ipod.sh @@ -22,8 +22,9 @@ usage() { usage: sync-to-ipod.sh [options] -n dry run; show what would change and touch nothing - -Q skip the counting pass; no percentage or estimate, but one less walk - of the source tree, which over SMB is the expensive part + -P count what needs copying first, so progress can show a percentage and + an estimate. Costs a second full traversal of both trees, which on a + FAT card of fifty thousand files is slower than the transfer itself -f copy even if the FAT32 check finds unacceptable paths -S skip submitting the Rockbox scrobbler log to Last.fm -B skip rebuilding the Rockbox database @@ -68,7 +69,7 @@ USAGE } dry_run=false -quick=false +counting=false force=false unmount=true scrobble=true @@ -76,10 +77,10 @@ database=true for argument in "$@"; do [ "$argument" = "--help" ] && usage help done -while getopts ":nQfSBUh" option; do +while getopts ":nPfSBUh" option; do case "$option" in n) dry_run=true ;; - Q) quick=true ;; + P) counting=true ;; f) force=true ;; S) scrobble=false ;; B) database=false ;; @@ -198,11 +199,15 @@ fi # thousand files over USB is minutes of apparent hang. Counting first costs a # second pass over the tree but means the transfer can show a real percentage # rather than a number that grows as rsync discovers more work. +# Counting is opt-in because it is not cheap. It walks and compares both trees +# in full, exactly as the transfer does, and on a FAT card holding fifty +# thousand files that traversal costs more than moving the data. Without it the +# progress line still shows the running count, the rate and the album in +# flight; only the percentage and the estimate are lost, and those were the +# least useful part of it. total=0 total_bytes=0 -if $quick; then - printf 'sync-to-ipod: skipping the count; no percentage or estimate\n' >&2 -else +if $counting; then printf 'sync-to-ipod: working out what needs copying...\n' >&2 # %l is the file's size, which is what makes an estimate possible. # Directories are dropped: rsync reports those too, with an inode size that -- 2.54.0 From f324b1b720c60dd3e7163f599566a0d9280a216c Mon Sep 17 00:00:00 2001 From: Emma Thorpe Date: Wed, 26 Aug 2026 18:24:12 +0100 Subject: [PATCH 3/4] feat: convert Rockbox's playback log on the laptop, skipping the plugin Scrobbling previously needed the on-device Last.fm plugin run by hand before each sync, to turn Rockbox's playback log into AUDIOSCROBBLER format. Forgetting that step means the sync submits nothing and quietly appears not to work. Core Rockbox writes ROCKBOX_DIR/playback.log whenever "play log" is enabled, with no plugin running at all. Each line is timestamp:elapsed_ms:length_ms:path. The only thing missing is tags, and that is exactly why the plugin exists: reading them back off the player is slow. Off the mirror it is free, because the same files are already there -- so the conversion belongs on the laptop, and the plugin can be skipped entirely. A play counts as listened at half the track's length, matching the plugin's savepct default, so the two cannot disagree about what a play was. A short play is a skip. An entry with no usable timestamp is refused rather than invented, which is the clockless case again. A path that maps to nothing in the mirror is counted and reported instead of guessed at. Rotated logs are picked up too; Rockbox starts a new one past half a megabyte. All of them are renamed aside together once Last.fm has accepted the batch. A .scrobbler.log is still read when the plugin has been run and left one. --- README.md | 14 ++- tests/test_submit_scrobbles.py | 122 ++++++++++++++++++++++++ tools/submit_scrobbles.py | 168 +++++++++++++++++++++++++++++++-- tools/sync-to-ipod.sh | 6 +- 4 files changed, 300 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 1f455e2..c36ba1c 100644 --- a/README.md +++ b/README.md @@ -286,8 +286,18 @@ The unmount is the point of doing this in a script. FAT32 has no journal and the device is reached through disk mode, so an interrupted write is corruption that needs `fsck.vfat` from another machine. -`submit_scrobbles.py` sends the Rockbox scrobbler log to Last.fm and sets it -aside. Rockbox writes `/.scrobbler.log` in AUDIOSCROBBLER 1.1 format, one +`submit_scrobbles.py` sends what was played to Last.fm and sets the logs aside. + +It reads **Rockbox's own `playback.log`**, which core Rockbox writes whenever +"play log" is enabled, with no plugin running. Each line is +`timestamp:elapsed_ms:length_ms:path` — a path and nothing else, which is why +the on-device scrobbler plugin exists at all: reading tags back off the player +is slow. Off the mirror it is free, so `--mirror` lets the conversion happen +here and the plugin never has to be run. A play counts as listened at half the +track's length, the same fraction the plugin uses, so the two cannot disagree +about what a play was. + +It still reads a `.scrobbler.log` if the plugin has been run and left one. Rockbox writes `/.scrobbler.log` in AUDIOSCROBBLER 1.1 format, one tab-separated line per track rated `L` for listened or `S` for skipped; only the listened ones are sent. It runs **before** the copy, since the plays already happened and a failed transfer is no reason to lose them. diff --git a/tests/test_submit_scrobbles.py b/tests/test_submit_scrobbles.py index d91e8b5..ae48c7b 100644 --- a/tests/test_submit_scrobbles.py +++ b/tests/test_submit_scrobbles.py @@ -187,3 +187,125 @@ def test_write_credentials_are_required(tmp_path, capsys, monkeypatch): assert code == 2 assert "LASTFM_API_SECRET" in capsys.readouterr().err + + +PLAYBACK_LOG = """1700000300:180000:245000:/Music/Pendulum/Immersion/01.mp3 +1700000200:9000:180000:/Music/Green Day/Dookie/07.mp3 +0:180000:245000:/Music/No/Clock/track.mp3 +malformed line without colons +""" + + +def tags_of(artist="Pendulum", title="Watercolour", album="Immersion", track="1/11"): + def runner(path): + return json.dumps( + {"format": {"tags": {"ARTIST": artist, "TITLE": title, + "ALBUM": album, "track": track}}} + ) + + return runner + + +def test_the_playback_log_format_is_four_fields(): + """timestamp:elapsed_ms:length_ms:path, written by Rockbox core.""" + plays = submit_scrobbles.parse_playback_log(PLAYBACK_LOG) + + assert len(plays) == 3 # the malformed line is dropped + assert plays[0] == (1700000300, 180000, 245000, "/Music/Pendulum/Immersion/01.mp3") + + +def test_a_device_path_maps_onto_the_mirror(): + assert submit_scrobbles.device_to_local( + "/Music/Pendulum/Immersion/01.mp3", "/Music", "/mnt/mirror" + ) == Path("/mnt/mirror/Pendulum/Immersion/01.mp3") + + +def test_a_path_outside_the_prefix_is_not_mapped(): + """Something played from elsewhere on the card is not in the mirror.""" + assert submit_scrobbles.device_to_local( + "/Podcasts/episode.mp3", "/Music", "/mnt/mirror" + ) is None + + +def test_a_path_at_the_card_root_maps_straight_across(): + assert submit_scrobbles.device_to_local( + "/Pendulum/Immersion/01.mp3", "/", "/mnt/mirror" + ) == Path("/mnt/mirror/Pendulum/Immersion/01.mp3") + + +def test_a_short_play_is_a_skip_not_a_scrobble(tmp_path, monkeypatch): + """Nine seconds of a three minute track. The on-device plugin uses the same + fraction, so the two never disagree about what counted as a play.""" + monkeypatch.setattr(Path, "is_file", lambda self: True) + + played, skipped, unresolved, timeless = submit_scrobbles.plays_from_playback_log( + PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() + ) + + assert skipped == 1 + assert [entry["timestamp"] for entry in played] == ["1700000300"] + + +def test_a_zero_timestamp_is_refused(tmp_path, monkeypatch): + """Without a real-time clock Rockbox logs ticks, not dates. Scrobbling + those would mean inventing when they happened.""" + monkeypatch.setattr(Path, "is_file", lambda self: True) + + _, _, _, timeless = submit_scrobbles.plays_from_playback_log( + PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() + ) + + assert timeless == 1 + + +def test_tags_come_from_the_mirror(tmp_path, monkeypatch): + """The log carries only a path -- which is precisely why the on-device + plugin exists. Off the mirror the tags are free.""" + monkeypatch.setattr(Path, "is_file", lambda self: True) + + played, _, _, _ = submit_scrobbles.plays_from_playback_log( + PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() + ) + + assert played[0]["artist"] == "Pendulum" + assert played[0]["album"] == "Immersion" + assert played[0]["trackNumber"] == "1" # "1/11" -> "1" + assert played[0]["duration"] == "245" # milliseconds -> seconds + + +def test_a_track_missing_from_the_mirror_is_counted_not_guessed(monkeypatch): + monkeypatch.setattr(Path, "is_file", lambda self: False) + + played, _, unresolved, _ = submit_scrobbles.plays_from_playback_log( + PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() + ) + + assert played == [] + # One: the skip and the clockless entry are filtered before the file is + # looked for, since neither would be submitted either way. + assert unresolved == 1 + + +def test_playback_logs_are_found_including_rotations(tmp_path): + """Rockbox rotates the log once it passes half a megabyte.""" + rockbox = tmp_path / ".rockbox" + rockbox.mkdir() + for name in ("playback.log", "playback_0001.log", "playback_0002.log"): + (rockbox / name).write_text("1700000000:1:1:/Music/a.mp3\n") + (rockbox / "empty.log").write_text("") + + found = submit_scrobbles.find_playback_logs(tmp_path) + + assert [path.name for path in found] == [ + "playback.log", "playback_0001.log", "playback_0002.log" + ] + + +def test_without_a_mirror_it_says_what_is_needed(tmp_path, capsys): + device = tmp_path / "IPOD" + (device / ".rockbox").mkdir(parents=True) + (device / ".rockbox" / "playback.log").write_text("1700000000:1:1:/Music/a.mp3\n") + + submit_scrobbles.main([str(device)], transport=fake_transport([])) + + assert "pass --mirror" in capsys.readouterr().err diff --git a/tools/submit_scrobbles.py b/tools/submit_scrobbles.py index 3468852..71d4840 100755 --- a/tools/submit_scrobbles.py +++ b/tools/submit_scrobbles.py @@ -31,6 +31,21 @@ BATCH = 50 # scrobble. LOG_NAMES = (".scrobbler.log", ".scrobbler-timeless.log") +# Rockbox core writes this whenever "play log" is on, with no plugin running: +# timestamp:elapsed_ms:length_ms:/Music/Artist/Album/Track.mp3 +# It is rotated once it grows past half a megabyte. Converting it needs tags, +# which is why the on-device plugin exists -- reading them back off the player +# is slow. Off the mirror it is free, so the plugin can be skipped entirely. +PLAYBACK_LOG_NAMES = ("playback.log", "playback_*.log") + +# The plugin counts a track as listened at savepct of its length, defaulting to +# fifty. Same rule here, or the two disagree about what a play is. +LISTENED_FRACTION = 0.5 + +# Below this a timestamp is not a wall-clock time. Without a real-time clock +# Rockbox logs ticks in milliseconds instead, which is not a date. +EARLIEST_PLAUSIBLE = 1_000_000_000 + SESSION_FILE = Path( os.getenv("XDG_CONFIG_HOME", Path.home() / ".config") ) / "music-mirror" / "lastfm.json" @@ -83,6 +98,98 @@ def parse_log(text): return played, skipped, timeless +def parse_playback_log(text): + """Return (timestamp, elapsed_ms, length_ms, path) for each logged play.""" + plays = [] + for line in text.splitlines(): + fields = line.strip().split(":", 3) + if len(fields) != 4: + continue + stamp, elapsed, length, path = fields + try: + plays.append((int(stamp), int(elapsed), int(length), path)) + except ValueError: + continue + return plays + + +def device_to_local(path, device_prefix, mirror): + """Map a path as the player sees it onto the mirror it was copied from.""" + prefix = "/" + device_prefix.strip("/") + if prefix != "/": + if not path.startswith(prefix + "/"): + return None + path = path[len(prefix) :] + return Path(mirror) / path.lstrip("/") + + +def read_tags(path, runner=None): + """Return the tags of a local file, via ffprobe.""" + runner = runner or _ffprobe + try: + payload = json.loads(runner(path)) + except (OSError, ValueError): + return {} + return { + key.lower(): value + for key, value in (payload.get("format", {}).get("tags") or {}).items() + } + + +def _ffprobe(path): + import subprocess + + return subprocess.run( + ["ffprobe", "-v", "error", "-show_entries", "format_tags", + "-of", "json", str(path)], + capture_output=True, text=True, check=True, + ).stdout + + +def plays_from_playback_log(text, device_prefix, mirror, runner=None): + """Return submittable entries, plus counts of what was left out. + + Skips are decided by the same fraction the on-device plugin uses, so the + two never disagree about what counted as a play. + """ + played, skipped, unresolved, timeless = [], 0, 0, 0 + for stamp, elapsed, length, device_path in parse_playback_log(text): + if stamp < EARLIEST_PLAUSIBLE: + timeless += 1 + continue + if length > 0 and elapsed < length * LISTENED_FRACTION: + skipped += 1 + continue + local = device_to_local(device_path, device_prefix, mirror) + tags = read_tags(local, runner) if local and local.is_file() else {} + artist = tags.get("artist") or tags.get("album_artist") or "" + title = tags.get("title") or "" + if not artist or not title: + unresolved += 1 + continue + played.append( + { + "artist": artist, + "track": title, + "album": tags.get("album", ""), + "trackNumber": (tags.get("track") or "").split("/")[0], + "duration": str(length // 1000) if length > 0 else "", + "timestamp": str(stamp), + "mbid": tags.get("musicbrainz_trackid", ""), + } + ) + played.sort(key=lambda entry: int(entry["timestamp"])) + return played, skipped, unresolved, timeless + + +def find_playback_logs(device): + """Return every playback log on a device, oldest first.""" + found = [] + for pattern in PLAYBACK_LOG_NAMES: + found.extend(sorted(Path(device).glob(f".rockbox/{pattern}"))) + return [path for path in found if path.is_file() and path.stat().st_size] + + def sign(params, secret): """Return Last.fm's method signature for a set of parameters. @@ -193,6 +300,18 @@ def find_log(device): def main(argv=None, transport=http_post): parser = argparse.ArgumentParser(description=__doc__) parser.add_argument("device", help="the mounted device, or a scrobbler log file") + parser.add_argument( + "--mirror", + help="the mirror the device was copied from. Given this, Rockbox's own" + " playback.log is converted here rather than needing the on-device" + " plugin run first", + ) + parser.add_argument( + "--device-prefix", + default="/Music", + help="where the music sits on the device, stripped when mapping a logged" + " path back onto the mirror", + ) parser.add_argument("--api-key", default=os.getenv("LASTFM_API_KEY")) parser.add_argument("--api-secret", default=os.getenv("LASTFM_API_SECRET")) parser.add_argument("--dry-run", action="store_true", help="parse and report only") @@ -203,12 +322,46 @@ def main(argv=None, transport=http_post): target = Path(args.device) log = target if target.is_file() else find_log(target) - if log is None: - print("no scrobbler log to submit", file=sys.stderr) + logs = [] + + if log is not None: + played, skipped, timeless = parse_log( + log.read_text(encoding="utf-8", errors="replace") + ) + unresolved = 0 + logs = [log] + print(f"{log}: {len(played)} listened, {skipped} skipped", file=sys.stderr) + elif args.mirror: + # No plugin has been run, but the core log is there. Tags come off the + # mirror, which is the only reason the plugin was needed at all. + logs = find_playback_logs(target) + if not logs: + print("no scrobbler log to submit", file=sys.stderr) + return 0 + text = "\n".join( + path.read_text(encoding="utf-8", errors="replace") for path in logs + ) + played, skipped, unresolved, timeless = plays_from_playback_log( + text, args.device_prefix, args.mirror + ) + print( + f"{len(logs)} playback log(s): {len(played)} listened, {skipped} skipped", + file=sys.stderr, + ) + if unresolved: + print( + f" {unresolved} could not be matched to a file in the mirror" + " and were left out", + file=sys.stderr, + ) + else: + print( + "no scrobbler log to submit. Rockbox's own playback.log can be used" + " instead -- pass --mirror so tags can be read from it.", + file=sys.stderr, + ) return 0 - played, skipped, timeless = parse_log(log.read_text(encoding="utf-8", errors="replace")) - print(f"{log}: {len(played)} listened, {skipped} skipped", file=sys.stderr) if timeless: print( f" {timeless} entries have no timestamp, so this target has no clock." @@ -245,9 +398,10 @@ def main(argv=None, transport=http_post): if not args.keep and accepted: # Renamed rather than deleted: if Last.fm quietly dropped something, # the evidence is still on the device. - aside = log.with_name(f"{log.name}.{played[-1]['timestamp']}.submitted") - log.rename(aside) - print(f"log moved to {aside.name}", file=sys.stderr) + for path in logs: + aside = path.with_name(f"{path.name}.{played[-1]['timestamp']}.submitted") + path.rename(aside) + print(f"log moved to {aside.name}", file=sys.stderr) return 0 diff --git a/tools/sync-to-ipod.sh b/tools/sync-to-ipod.sh index 206293d..97690db 100755 --- a/tools/sync-to-ipod.sh +++ b/tools/sync-to-ipod.sh @@ -158,7 +158,11 @@ if $scrobble; then else scrobble_options=() $dry_run && scrobble_options+=(--dry-run) - python3 "$here/submit_scrobbles.py" "${scrobble_options[@]}" "$destination" || + # --mirror lets it convert Rockbox's own playback.log, so the on-device + # scrobbler plugin never has to be run. The device root, not the music + # directory: the logs live in .rockbox. + python3 "$here/submit_scrobbles.py" "${scrobble_options[@]}" \ + --mirror "$mirror" --device-prefix "$device_prefix" "$mounted_on" || die "submitting scrobbles failed; nothing has been copied" fi fi -- 2.54.0 From 374a17474f467236234ffe9a0eed89544101053e Mon Sep 17 00:00:00 2001 From: Emma Thorpe Date: Wed, 26 Aug 2026 18:32:05 +0100 Subject: [PATCH 4/4] fix: never discard a play that has not been submitted Setting the logs aside after a successful submission threw away more than it had submitted. A play of a track missing from the mirror -- not yet copied, or its tags unreadable -- was counted as unresolved and then carried off with the rest, with nothing to retry it. The play happened and was lost. Two obligations now, kept separate. The original log is renamed rather than deleted, so a mistake here cannot destroy the record. And every play that was not submitted is written back into a live log, so the next run attempts it again: the unmatched ones, and anything in a batch that failed. Submission is recorded batch by batch as each is accepted, so a failure partway through knows exactly what got through. The remainder is written back and nothing is sent twice. When nothing at all is accepted the logs are left untouched. Skips and clockless entries are deliberately not retained. Neither can ever be submitted, so keeping them would mean reprocessing them for ever, and the untouched original holds them regardless. Also fixes a way to lose the lot: read_tags caught OSError and ValueError, but ffprobe failing raises CalledProcessError, which is neither. A single unreadable file aborted the whole submission rather than costing one unidentified play. --- README.md | 25 +++++- tests/test_submit_scrobbles.py | 146 ++++++++++++++++++++++++++++++--- tools/submit_scrobbles.py | 141 +++++++++++++++++++++++++------ 3 files changed, 273 insertions(+), 39 deletions(-) diff --git a/README.md b/README.md index c36ba1c..b77b357 100644 --- a/README.md +++ b/README.md @@ -309,8 +309,29 @@ real-time clock Rockbox writes `/.scrobbler-timeless.log` with every timestamp set to zero; those are counted and reported but never submitted, because scrobbling them would mean inventing when they happened. -The log is renamed rather than deleted once accepted. If Last.fm quietly -dropped something, the evidence is still on the device. +### Nothing played is thrown away + +Two separate obligations, because a play that happened and never reached +Last.fm is gone for good. + +**The original is renamed, never deleted.** If Last.fm quietly dropped +something, the evidence is still on the device as `playback.log..submitted`. + +**Anything not submitted is written back** into a live log for the next run: + +| Outcome | What happens to it | +| ------------------------------ | ----------------------------------------- | +| Accepted by Last.fm | dropped from the live log | +| Not in the mirror yet | written back, tried again next run | +| In a batch that failed | written back, tried again next run | +| Nothing accepted at all | logs left completely untouched | +| A skip, or no usable timestamp | not retained — neither can ever be submitted, and the original still has it | + +The batch boundary matters: submission is recorded as each batch is accepted, +so a failure partway through knows exactly what got through and writes back +only the remainder. No duplicates, no losses. + +A file `ffprobe` cannot read costs one unidentified play, not the run. `check_fat32.py` reports paths a FAT32 device will not accept — reserved characters, trailing dots and spaces, over-long components and paths, and names diff --git a/tests/test_submit_scrobbles.py b/tests/test_submit_scrobbles.py index ae48c7b..2e98b8f 100644 --- a/tests/test_submit_scrobbles.py +++ b/tests/test_submit_scrobbles.py @@ -1,4 +1,5 @@ import json +import subprocess import sys from pathlib import Path @@ -238,12 +239,12 @@ def test_a_short_play_is_a_skip_not_a_scrobble(tmp_path, monkeypatch): fraction, so the two never disagree about what counted as a play.""" monkeypatch.setattr(Path, "is_file", lambda self: True) - played, skipped, unresolved, timeless = submit_scrobbles.plays_from_playback_log( + result = submit_scrobbles.plays_from_playback_log( PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() ) - assert skipped == 1 - assert [entry["timestamp"] for entry in played] == ["1700000300"] + assert result.skipped == 1 + assert [entry["timestamp"] for entry in result.played] == ["1700000300"] def test_a_zero_timestamp_is_refused(tmp_path, monkeypatch): @@ -251,11 +252,11 @@ def test_a_zero_timestamp_is_refused(tmp_path, monkeypatch): those would mean inventing when they happened.""" monkeypatch.setattr(Path, "is_file", lambda self: True) - _, _, _, timeless = submit_scrobbles.plays_from_playback_log( + result = submit_scrobbles.plays_from_playback_log( PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() ) - assert timeless == 1 + assert result.timeless == 1 def test_tags_come_from_the_mirror(tmp_path, monkeypatch): @@ -263,9 +264,9 @@ def test_tags_come_from_the_mirror(tmp_path, monkeypatch): plugin exists. Off the mirror the tags are free.""" monkeypatch.setattr(Path, "is_file", lambda self: True) - played, _, _, _ = submit_scrobbles.plays_from_playback_log( + played = submit_scrobbles.plays_from_playback_log( PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() - ) + ).played assert played[0]["artist"] == "Pendulum" assert played[0]["album"] == "Immersion" @@ -276,14 +277,16 @@ def test_tags_come_from_the_mirror(tmp_path, monkeypatch): def test_a_track_missing_from_the_mirror_is_counted_not_guessed(monkeypatch): monkeypatch.setattr(Path, "is_file", lambda self: False) - played, _, unresolved, _ = submit_scrobbles.plays_from_playback_log( + result = submit_scrobbles.plays_from_playback_log( PLAYBACK_LOG, "/Music", "/mnt/mirror", runner=tags_of() ) - assert played == [] + assert result.played == [] # One: the skip and the clockless entry are filtered before the file is # looked for, since neither would be submitted either way. - assert unresolved == 1 + assert result.unresolved == 1 + # And that one play is kept, so a later run can try it again. + assert len(result.retain) == 1 def test_playback_logs_are_found_including_rotations(tmp_path): @@ -309,3 +312,126 @@ def test_without_a_mirror_it_says_what_is_needed(tmp_path, capsys): submit_scrobbles.main([str(device)], transport=fake_transport([])) assert "pass --mirror" in capsys.readouterr().err + + +MIRROR = "/mnt/mirror" + + +def stub_ffprobe(monkeypatch, **tags): + """Answer for anything under the mirror without invoking ffprobe.""" + monkeypatch.setattr(submit_scrobbles, "_ffprobe", tags_of(**tags)) + + +def only_mirror_files_exist(monkeypatch, resolvable=None): + """Make the mirror's files appear to exist, and nothing else. + + Patching is_file wholesale makes the device directory look like a log file, + which sends main() down the .scrobbler.log path instead. + """ + real = Path.is_file + + def patched(self): + text = str(self) + if text.startswith(MIRROR): + return resolvable is None or text == resolvable + return real(self) + + monkeypatch.setattr(Path, "is_file", patched) + + +def playback_device(tmp_path, log=PLAYBACK_LOG): + device = tmp_path / "IPOD" + (device / ".rockbox").mkdir(parents=True) + (device / ".rockbox" / "playback.log").write_text(log) + return device + + +def test_a_failed_submission_keeps_every_log(tmp_path, monkeypatch): + """Nothing got through, so nothing may be set aside.""" + only_mirror_files_exist(monkeypatch) + stub_ffprobe(monkeypatch) + monkeypatch.setattr(submit_scrobbles, "load_session", lambda: "sk") + device = playback_device(tmp_path) + transport = fake_transport([{"error": 29, "message": "Rate limit"}]) + + code = submit_scrobbles.main( + [str(device), "--mirror", MIRROR, "--api-key", "k", "--api-secret", "s"], + transport=transport, + ) + + assert code == 1 + assert (device / ".rockbox" / "playback.log").is_file() + assert not list((device / ".rockbox").glob("*.submitted")) + + +def test_an_unmatched_play_is_written_back_not_lost(tmp_path, monkeypatch, capsys): + """A track the mirror does not yet hold is still a play that happened. It + is kept so a later run, after the file has been copied, can submit it.""" + monkeypatch.setattr(submit_scrobbles, "load_session", lambda: "sk") + # Only the first track resolves; the rest are absent from the mirror. + only_mirror_files_exist(monkeypatch, f"{MIRROR}/Pendulum/Immersion/01.mp3") + stub_ffprobe(monkeypatch) + log = ( + "1700000300:180000:245000:/Music/Pendulum/Immersion/01.mp3\n" + "1700000400:180000:245000:/Music/Missing/Album/09.mp3\n" + ) + device = playback_device(tmp_path, log) + transport = fake_transport([{"scrobbles": {"@attr": {"accepted": 1, "ignored": 0}}}]) + + code = submit_scrobbles.main( + [str(device), "--mirror", MIRROR, "--api-key", "k", "--api-secret", "s"], + transport=transport, + ) + + assert code == 0 + rockbox = device / ".rockbox" + # The original is preserved untouched... + assert list(rockbox.glob("playback.log.*.submitted")) + # ...and the unmatched play is back in a live log for the next attempt. + written = (rockbox / "playback.log").read_text() + assert "Missing/Album/09.mp3" in written + assert "Pendulum/Immersion/01.mp3" not in written + + +def test_the_original_is_renamed_rather_than_deleted(tmp_path, monkeypatch): + """If Last.fm quietly dropped something, the evidence stays on the device.""" + only_mirror_files_exist(monkeypatch) + stub_ffprobe(monkeypatch) + monkeypatch.setattr(submit_scrobbles, "load_session", lambda: "sk") + device = playback_device(tmp_path) + transport = fake_transport([{"scrobbles": {"@attr": {"accepted": 1, "ignored": 0}}}]) + + submit_scrobbles.main( + [str(device), "--mirror", MIRROR, "--api-key", "k", "--api-secret", "s"], + transport=transport, + ) + + aside = list((device / ".rockbox").glob("playback.log.*.submitted")) + assert len(aside) == 1 + assert PLAYBACK_LOG.splitlines()[0] in aside[0].read_text() + + +def test_keep_leaves_everything_alone(tmp_path, monkeypatch): + only_mirror_files_exist(monkeypatch) + stub_ffprobe(monkeypatch) + monkeypatch.setattr(submit_scrobbles, "load_session", lambda: "sk") + device = playback_device(tmp_path) + transport = fake_transport([{"scrobbles": {"@attr": {"accepted": 1, "ignored": 0}}}]) + + submit_scrobbles.main( + [str(device), "--mirror", MIRROR, "--keep", + "--api-key", "k", "--api-secret", "s"], + transport=transport, + ) + + assert (device / ".rockbox" / "playback.log").read_text() == PLAYBACK_LOG + assert not list((device / ".rockbox").glob("*.submitted")) + + +def test_a_file_ffprobe_cannot_read_does_not_abandon_the_rest(monkeypatch): + """CalledProcessError is not an OSError, so one bad file used to take the + whole submission with it.""" + def broken(path): + raise subprocess.CalledProcessError(1, "ffprobe") + + assert submit_scrobbles.read_tags(Path("/mnt/mirror/x.mp3"), runner=broken) == {} diff --git a/tools/submit_scrobbles.py b/tools/submit_scrobbles.py index 71d4840..aba0bb1 100755 --- a/tools/submit_scrobbles.py +++ b/tools/submit_scrobbles.py @@ -14,11 +14,13 @@ import argparse import hashlib import json import os +import subprocess import sys import time import urllib.error import urllib.parse import urllib.request +from dataclasses import dataclass from pathlib import Path API_ROOT = "https://ws.audioscrobbler.com/2.0/" @@ -124,11 +126,16 @@ def device_to_local(path, device_prefix, mirror): def read_tags(path, runner=None): - """Return the tags of a local file, via ffprobe.""" + """Return the tags of a local file, via ffprobe. Empty if it cannot be read. + + A file ffprobe chokes on is one play left unidentified, not a reason to + abandon the rest -- and CalledProcessError is not an OSError, so catching + the obvious things is not enough. + """ runner = runner or _ffprobe try: payload = json.loads(runner(path)) - except (OSError, ValueError): + except (OSError, ValueError, subprocess.SubprocessError): return {} return { key.lower(): value @@ -137,8 +144,6 @@ def read_tags(path, runner=None): def _ffprobe(path): - import subprocess - return subprocess.run( ["ffprobe", "-v", "error", "-show_entries", "format_tags", "-of", "json", str(path)], @@ -146,28 +151,58 @@ def _ffprobe(path): ).stdout +@dataclass +class Conversion: + """What a playback log turned into, and what must not be thrown away. + + `retain` holds the raw lines of plays that were real but could not be + submitted -- a track absent from the mirror, usually because the sync had + not copied it yet. Those are written back so a later run can try again. + Skips and clockless entries are not retained: neither can ever be + submitted, and the untouched original is set aside regardless. + """ + + played: list + skipped: int = 0 + unresolved: int = 0 + timeless: int = 0 + retain: list = None + + def __post_init__(self): + if self.retain is None: + self.retain = [] + + def plays_from_playback_log(text, device_prefix, mirror, runner=None): - """Return submittable entries, plus counts of what was left out. + """Return the conversion of a playback log. Skips are decided by the same fraction the on-device plugin uses, so the two never disagree about what counted as a play. """ - played, skipped, unresolved, timeless = [], 0, 0, 0 - for stamp, elapsed, length, device_path in parse_playback_log(text): + result = Conversion(played=[]) + for line in text.splitlines(): + parsed = parse_playback_log(line) + if not parsed: + continue + stamp, elapsed, length, device_path = parsed[0] if stamp < EARLIEST_PLAUSIBLE: - timeless += 1 + result.timeless += 1 continue if length > 0 and elapsed < length * LISTENED_FRACTION: - skipped += 1 + result.skipped += 1 continue local = device_to_local(device_path, device_prefix, mirror) tags = read_tags(local, runner) if local and local.is_file() else {} artist = tags.get("artist") or tags.get("album_artist") or "" title = tags.get("title") or "" if not artist or not title: - unresolved += 1 + # A real play of a track this run could not identify. Kept, so a + # later run -- after the file has been copied, or the tags fixed -- + # can submit it rather than the play being lost. + result.unresolved += 1 + result.retain.append(line) continue - played.append( + result.played.append( { "artist": artist, "track": title, @@ -176,10 +211,11 @@ def plays_from_playback_log(text, device_prefix, mirror, runner=None): "duration": str(length // 1000) if length > 0 else "", "timestamp": str(stamp), "mbid": tags.get("musicbrainz_trackid", ""), + "line": line, } ) - played.sort(key=lambda entry: int(entry["timestamp"])) - return played, skipped, unresolved, timeless + result.played.sort(key=lambda entry: int(entry["timestamp"])) + return result def find_playback_logs(device): @@ -259,7 +295,7 @@ def batch_params(entries): return params -def submit(entries, key, secret, session, transport, delay=1.0): +def submit(entries, key, secret, session, transport, delay=1.0, on_sent=None): """Submit every entry. Returns how many the service accepted. Batches are counted as they succeed rather than at the end, so a failure @@ -275,6 +311,8 @@ def submit(entries, key, secret, session, transport, delay=1.0): block = payload.get("scrobbles", {}) summary = block.get("@attr", block) accepted += int(summary.get("accepted", len(chunk))) + if on_sent is not None: + on_sent(chunk) ignored = int(summary.get("ignored", 0)) if ignored: print(f" {ignored} of {len(chunk)} ignored by Last.fm", file=sys.stderr) @@ -324,6 +362,7 @@ def main(argv=None, transport=http_post): log = target if target.is_file() else find_log(target) logs = [] + conversion = None if log is not None: played, skipped, timeless = parse_log( log.read_text(encoding="utf-8", errors="replace") @@ -341,8 +380,12 @@ def main(argv=None, transport=http_post): text = "\n".join( path.read_text(encoding="utf-8", errors="replace") for path in logs ) - played, skipped, unresolved, timeless = plays_from_playback_log( - text, args.device_prefix, args.mirror + conversion = plays_from_playback_log(text, args.device_prefix, args.mirror) + played = conversion.played + skipped, unresolved, timeless = ( + conversion.skipped, + conversion.unresolved, + conversion.timeless, ) print( f"{len(logs)} playback log(s): {len(played)} listened, {skipped} skipped", @@ -350,8 +393,8 @@ def main(argv=None, transport=http_post): ) if unresolved: print( - f" {unresolved} could not be matched to a file in the mirror" - " and were left out", + f" {unresolved} could not be matched to a file in the mirror." + " Those plays are kept for a later run rather than discarded.", file=sys.stderr, ) else: @@ -388,22 +431,66 @@ def main(argv=None, transport=http_post): session = authorise(args.api_key, args.api_secret, transport) save_session(session) + # Recorded as each batch is accepted, so a failure partway through knows + # exactly what got through and what did not. + sent = [] try: - accepted = submit(played, args.api_key, args.api_secret, session, transport) + accepted = submit( + played, args.api_key, args.api_secret, session, transport, + on_sent=sent.extend, + ) except LastfmError as error: - print(f"submission failed: {error}", file=sys.stderr) + print(f"submission failed after {len(sent)} scrobbles: {error}", file=sys.stderr) + keep_history(logs, played, sent, conversion, args.keep) return 1 print(f"{accepted} scrobbles accepted", file=sys.stderr) - if not args.keep and accepted: - # Renamed rather than deleted: if Last.fm quietly dropped something, - # the evidence is still on the device. - for path in logs: - aside = path.with_name(f"{path.name}.{played[-1]['timestamp']}.submitted") - path.rename(aside) - print(f"log moved to {aside.name}", file=sys.stderr) + keep_history(logs, played, sent, conversion, args.keep) return 0 +def keep_history(logs, played, sent, conversion, keep): + """Set the logs aside, writing back anything still owed a submission. + + Two separate obligations. The original is preserved untouched, renamed + rather than deleted, so a play is never lost to a mistake here. And any + play that was not submitted -- unmatched, or in a batch that failed -- is + written back into a live log, so the next run tries it again instead of it + quietly vanishing with the rest. + """ + if keep or not logs: + if keep: + print("logs left in place", file=sys.stderr) + return + + submitted = {id(entry) for entry in sent} + # A .scrobbler.log was converted by the on-device plugin and carries no + # per-line record, so there is nothing to write back for it -- only the + # rename below, which loses nothing. + pending = list(conversion.retain) if conversion is not None else [] + pending += [ + entry["line"] for entry in played + if "line" in entry and id(entry) not in submitted + ] + + if not sent: + print("nothing was accepted; logs left untouched", file=sys.stderr) + return + + stamp = played[-1]["timestamp"] if played else "0" + for path in logs: + path.rename(path.with_name(f"{path.name}.{stamp}.submitted")) + + if pending: + live = logs[0].with_name("playback.log") + live.write_text("\n".join(pending) + "\n", encoding="utf-8") + print( + f"{len(pending)} plays not submitted were written back to" + f" {live.name} for the next run", + file=sys.stderr, + ) + print(f"{len(logs)} log(s) set aside as .submitted", file=sys.stderr) + + if __name__ == "__main__": sys.exit(main()) -- 2.54.0