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

@@ -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.<ts>.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

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) == {}

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())