debug: add comprehensive logging for TorBox state transition
All checks were successful
CI/CD / Build & Push Docker Image (push) Successful in 1m13s

Add logging at key points in the download flow to diagnose why TorBox
downloads get stuck in 'downloading' state despite completion:

- Log initial state at processFiles start
- Log when download loop exits
- Log when onSuccess callback is invoked
- Log condition evaluation in updateTorrent
- Log when state is set to pausedUP

Also fix missing return after onFailed for empty symlink path edge case.

Part of dcy-355 investigation.

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
This commit is contained in:
2026-01-31 11:46:33 -08:00
committed by John Ogle
parent 43a94118f4
commit 3f96382e76

View File

@@ -53,6 +53,12 @@ func (s *Store) processFiles(torrent *Torrent, debridTorrent *types.Torrent, imp
return
}
s.logger.Debug().
Str("torrent_name", debridTorrent.Name).
Str("debrid_status", debridTorrent.Status).
Str("torrent_state", torrent.State).
Msg("processFiles started")
deb := s.debrid.Debrid(debridTorrent.Debrid)
client := deb.Client()
downloadingStatuses := client.GetDownloadingStatus()
@@ -96,6 +102,12 @@ func (s *Store) processFiles(torrent *Torrent, debridTorrent *types.Torrent, imp
nextInterval := min(s.refreshInterval*2, 30*time.Second)
backoff.Reset(nextInterval)
}
s.logger.Debug().
Str("torrent_name", debridTorrent.Name).
Str("debrid_status", debridTorrent.Status).
Msg("Download loop exited, proceeding to post-processing")
var torrentSymlinkPath, torrentRclonePath string
debridTorrent.Arr = _arr
@@ -114,6 +126,11 @@ func (s *Store) processFiles(torrent *Torrent, debridTorrent *types.Torrent, imp
}
onSuccess := func(torrentSymlinkPath string) {
s.logger.Debug().
Str("torrent_name", debridTorrent.Name).
Str("symlink_path", torrentSymlinkPath).
Str("debrid_status", debridTorrent.Status).
Msg("onSuccess called")
torrent.TorrentPath = torrentSymlinkPath
s.updateTorrent(torrent, debridTorrent)
s.logger.Info().Msgf("Adding %s took %s", debridTorrent.Name, time.Since(timer))
@@ -201,6 +218,7 @@ func (s *Store) processFiles(torrent *Torrent, debridTorrent *types.Torrent, imp
if torrentSymlinkPath == "" {
err = fmt.Errorf("symlink path is empty for %s", debridTorrent.Name)
onFailed(err)
return
}
onSuccess(torrentSymlinkPath)
return
@@ -320,6 +338,13 @@ func (s *Store) updateTorrent(t *Torrent, debridTorrent *types.Torrent) *Torrent
return t
}
s.logger.Debug().
Str("torrent_name", t.Name).
Str("debrid_status", debridTorrent.Status).
Str("torrent_path", t.TorrentPath).
Str("current_state", t.State).
Msg("updateTorrent called")
if debridClient := s.debrid.Clients()[debridTorrent.Debrid]; debridClient != nil {
if debridTorrent.Status != "downloaded" {
_ = debridClient.UpdateTorrent(debridTorrent)
@@ -332,6 +357,9 @@ func (s *Store) updateTorrent(t *Torrent, debridTorrent *types.Torrent) *Torrent
// This is a direct fix for TorBox where IsReady() might fail due to
// progress/AmountLeft calculation issues.
if debridTorrent.Status == "downloaded" && t.TorrentPath != "" {
s.logger.Debug().
Str("torrent_name", t.Name).
Msg("Setting state to pausedUP (downloaded + path)")
t.State = "pausedUP"
t.Progress = 1.0
t.AmountLeft = 0
@@ -339,7 +367,20 @@ func (s *Store) updateTorrent(t *Torrent, debridTorrent *types.Torrent) *Torrent
return t
}
// Log why the primary condition failed
s.logger.Debug().
Str("torrent_name", t.Name).
Str("debrid_status", debridTorrent.Status).
Str("torrent_path", t.TorrentPath).
Bool("is_ready", t.IsReady()).
Float64("progress", t.Progress).
Int64("amount_left", t.AmountLeft).
Msg("Primary pausedUP condition failed, checking IsReady")
if t.IsReady() {
s.logger.Debug().
Str("torrent_name", t.Name).
Msg("Setting state to pausedUP (IsReady=true)")
t.State = "pausedUP"
s.torrents.Update(t)
return t