hpz937/zurg
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add proper logging

Browse Source
This commit is contained in:
Ben Sarmiento
2023-11-05 01:23:41 +01:00
parent 1b116c2194
commit a9c71a3e93
11 changed files with 103 additions and 96 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
internal/torrent/hooks.go
View File

@@ -3,10 +3,10 @@ package torrent
import (
"bytes"
"fmt"
"log"
"os/exec"
"github.com/debridmediamanager.com/zurg/internal/config"
"github.com/debridmediamanager.com/zurg/pkg/logutil"
)
type ScriptExecutor struct {
@@ -30,15 +30,18 @@ func (se *ScriptExecutor) Execute() (string, error) {
}
func OnLibraryUpdateHook(config config.ConfigInterface) {
rlog := logutil.NewLogger()
log := rlog.Named("hooks")
executor := &ScriptExecutor{
Script: config.GetOnLibraryUpdate(),
}
output, err := executor.Execute()
if err != nil {
log.Printf("Failed to execute hook on_library_update:\n%v\n", err)
log.Errorf("Failed to execute hook on_library_update: %v", err)
return
}
if output != "" {
log.Printf("Output of hook on_library_update:\n%s\n", output)
log.Infof("Output of hook on_library_update:\n%s", output)
}
}

94
internal/torrent/manager.go
View File

@@ -3,7 +3,6 @@ package torrent
import (
"encoding/gob"
"fmt"
"log"
"math"
"os"
"strings"
@@ -11,8 +10,10 @@ import (
"time"
"github.com/debridmediamanager.com/zurg/internal/config"
"github.com/debridmediamanager.com/zurg/pkg/logutil"
"github.com/debridmediamanager.com/zurg/pkg/realdebrid"
"github.com/hashicorp/golang-lru/v2/expirable"
"go.uber.org/zap"
)
type TorrentManager struct {
@@ -26,6 +27,7 @@ type TorrentManager struct {
directoryMap map[string][]string
processedTorrents map[string][]string
mu *sync.Mutex
log *zap.SugaredLogger
}
// NewTorrentManager creates a new torrent manager
@@ -40,16 +42,14 @@ func NewTorrentManager(config config.ConfigInterface, cache *expirable.LRU[strin
directoryMap: make(map[string][]string),
processedTorrents: make(map[string][]string),
mu: &sync.Mutex{},
log: logutil.NewLogger().Named("manager"),
}
// Initialize torrents for the first time
log.Println("Initializing torrents")
t.mu.Lock()
log.Println("Fetching torrents")
t.torrents = t.getFreshListFromAPI()
t.checksum = t.getChecksum()
t.mu.Unlock()
log.Println("Finished fetching torrents")
// log.Println("First checksum", t.checksum)
@@ -162,13 +162,13 @@ func (t *TorrentManager) getChecksum() string {
totalCount = torrentsResp.totalCount
case count = <-countChan:
case err := <-errChan:
log.Printf("Error: %v\n", err)
t.log.Errorf("Checksum API Error: %v\n", err)
return ""
}
}
if len(torrents) == 0 {
log.Println("Huh, no torrents returned")
t.log.Error("Huh, no torrents returned")
return ""
}
@@ -178,7 +178,7 @@ func (t *TorrentManager) getChecksum() string {
// startRefreshJob periodically refreshes the torrents
func (t *TorrentManager) startRefreshJob() {
log.Println("Starting periodic refresh")
t.log.Info("Starting periodic refresh")
for {
<-time.After(time.Duration(t.config.GetRefreshEverySeconds()) * time.Second)
@@ -221,7 +221,7 @@ func (t *TorrentManager) startRefreshJob() {
func (t *TorrentManager) getFreshListFromAPI() []Torrent {
torrents, _, err := realdebrid.GetTorrents(t.config.GetToken(), 0)
if err != nil {
log.Printf("Cannot get torrents: %v\n", err)
t.log.Errorf("Cannot get torrents: %v\n", err)
return nil
}
@@ -244,7 +244,7 @@ func (t *TorrentManager) getFreshListFromAPI() []Torrent {
}
}
log.Printf("Fetched %d torrents", len(torrentsV2))
t.log.Infof("Fetched %d torrents", len(torrentsV2))
return torrentsV2
}
@@ -267,10 +267,10 @@ func (t *TorrentManager) addMoreInfo(torrent *Torrent) {
return
}
// log.Println("Getting info for", torrent.ID)
// t.log.Println("Getting info for", torrent.ID)
info, err := realdebrid.GetTorrentInfo(t.config.GetToken(), torrent.ID)
if err != nil {
log.Printf("Cannot get info: %v\n", err)
t.log.Errorf("Cannot get info: %v\n", err)
return
}
@@ -298,19 +298,21 @@ func (t *TorrentManager) addMoreInfo(torrent *Torrent) {
})
}
if len(selectedFiles) > len(info.Links) && info.Progress == 100 {
log.Printf("Some links has expired for %s, %s: %d selected but only %d link(s)\n", info.ID, info.Name, len(selectedFiles), len(info.Links))
t.log.Debugf("Some links has expired for %s %s: %d selected but only %d link(s)", info.ID, info.Name, len(selectedFiles), len(info.Links))
// chaotic file means RD will not output the desired file selection
// e.g. even if we select just a single mkv, it will output a rar
var isChaotic bool
selectedFiles, isChaotic = t.organizeChaos(info, selectedFiles)
if isChaotic {
log.Println("This torrent is unfixable, it's always returning an unstreamable link, ignoring", info.ID, info.Name)
t.log.Infof("Torrent %s %s is unfixable, it's always returning an unstreamable link, ignoring", info.ID, info.Name)
t.log.Debugf("You can try fixing it yourself magnet:?xt=urn:btih:%s", info.Hash)
} else {
if len(streamableFiles) > 1 {
log.Println("Marking for repair", info.ID, info.Name)
t.log.Infof("Torrent %s %s marked for repair", info.ID, info.Name)
forRepair = true
} else {
log.Println("This torrent is unfixable, the lone streamable link has expired, ignoring", info.ID, info.ID)
t.log.Infof("Torrent %s %s is unfixable, the lone streamable link has expired, ignoring", info.ID, info.Name)
t.log.Debugf("You can try fixing it yourself magnet:?xt=urn:btih:%s", info.Hash)
}
}
} else {
@@ -352,7 +354,6 @@ func (t *TorrentManager) mapToDirectories() {
// for every group, iterate over every torrent
// and then sprinkle/distribute the torrents to the directories of the group
for group, directories := range groupMap {
log.Printf("Processing directory group '%s', sequence: %s\n", group, strings.Join(directories, " > "))
counter := make(map[string]int)
for i := range t.torrents {
// don't process torrents that are already mapped if it is not the first run
@@ -398,15 +399,14 @@ func (t *TorrentManager) mapToDirectories() {
sum += count
}
if sum > 0 {
log.Printf("Directory group processed: %s %v %d\n", group, counter, sum)
t.log.Infof("Group processing completed: %s %v total: %d", group, counter, sum)
} else {
log.Println("No new additions to directory group", group)
t.log.Info("No new additions to directory group", group)
}
}
default:
log.Println("Unknown config version")
t.log.Error("Unknown config version")
}
log.Println("Finished mapping to directories")
}
// getByID returns a torrent by its ID
@@ -424,7 +424,7 @@ func (t *TorrentManager) writeToFile(torrent *Torrent) {
filePath := fmt.Sprintf("data/%s.bin", torrent.ID)
file, err := os.Create(filePath)
if err != nil {
log.Fatalf("Failed creating file: %s", err)
t.log.Fatalf("Failed creating file: %s", err)
return
}
defer file.Close()
@@ -468,14 +468,14 @@ func (t *TorrentManager) repairAll(wg *sync.WaitGroup) {
wg.Wait()
for _, torrent := range t.torrents {
if torrent.ForRepair {
log.Println("Issues were detected on", torrent.Name, "; fixing...")
t.log.Infof("Issues were detected on %s %s; fixing...", torrent.ID, torrent.Name)
t.repair(torrent.ID, torrent.SelectedFiles, true)
}
if len(torrent.Links) == 0 && torrent.Progress == 100 {
// If the torrent has no links
// and already processing repair
// delete it!
log.Println("Deleting", torrent.Name, "as it has no links")
t.log.Infof("Deleting broken torrent %s %s as it doesn't contain any files", torrent.ID, torrent.Name)
realdebrid.DeleteTorrent(t.config.GetToken(), torrent.ID)
}
}
@@ -496,7 +496,7 @@ func (t *TorrentManager) repair(torrentID string, selectedFiles []File, tryReins
}
}
if found {
log.Println("Repair in progress, skipping", torrentID)
t.log.Infof("Repair in progress, skipping %s", torrentID)
return
}
@@ -519,16 +519,16 @@ func (t *TorrentManager) repair(torrentID string, selectedFiles []File, tryReins
}
}
if len(missingFiles) == 0 {
log.Println(torrent.Name, "is already repaired")
t.log.Infof("Torrent %s %s is already repaired", torrent.ID, torrent.Name)
return
}
// then we repair it!
log.Println("Repairing torrent", torrentID)
t.log.Infof("Repairing torrent %s %s", torrent.ID, torrent.Name)
// check if we can still add more downloads
proceed := t.canCapacityHandle()
if !proceed {
log.Println("Cannot add more torrents, exiting")
t.log.Error("Cannot add more torrents, exiting")
return
}
@@ -556,8 +556,7 @@ func (t *TorrentManager) repair(torrentID string, selectedFiles []File, tryReins
// we will download 1 extra streamable file to force a redownload of the missing files
// or if there's only 1 missing file, we will download 1 more to prevent a rename
missingFilesPlus1 := strings.Join(getFileIDs(missingFiles), ",")
missingFilesPlus1 += fmt.Sprintf(",%d", otherStreamableFileIDs[0])
log.Println("Trying to reinsert with 1 extra file", missingFilesPlus1)
t.log.Infof("Redownloading %d missing files", len(missingFiles))
t.reinsertTorrent(torrent, missingFilesPlus1, false)
} else if len(selectedFiles) > 1 {
// if not, last resort: add only the missing files but do it in 2 batches
@@ -565,25 +564,28 @@ func (t *TorrentManager) repair(torrentID string, selectedFiles []File, tryReins
missingFiles1 := strings.Join(getFileIDs(missingFiles[:half]), ",")
missingFiles2 := strings.Join(getFileIDs(missingFiles[half:]), ",")
if missingFiles1 != "" {
log.Println("Trying to reinsert with 1/2 batches", missingFiles1)
t.log.Infof("Redownloading %d missing files; batch 1 of 2", len(missingFiles1))
t.reinsertTorrent(torrent, missingFiles1, false)
}
if missingFiles2 != "" {
log.Println("Trying to reinsert with 2/2 batches", missingFiles2)
t.log.Infof("Redownloading %d missing files; batch 2 of 2", len(missingFiles2))
t.reinsertTorrent(torrent, missingFiles2, false)
} else {
t.log.Info("No other missing files left to reinsert")
}
} else {
log.Println("Cannot repair as the single link cached in RD for this torrent is already broken", torrent.ID, torrent.Name)
t.log.Infof("Torrent %s %s is unfixable as the only link cached in RD is already broken", torrent.ID, torrent.Name)
t.log.Debugf("You can try fixing it yourself magnet:?xt=urn:btih:%s", torrent.Hash)
return
}
log.Println("Waiting for downloads to finish")
t.log.Info("Waiting for downloads to finish")
}
}
func (t *TorrentManager) reinsertTorrent(torrent *Torrent, missingFiles string, deleteIfFailed bool) bool {
// if missingFiles is not provided, look for missing files
if missingFiles == "" {
log.Println("Reinserting whole torrent", torrent.Name)
t.log.Info("Redownloading whole torrent", torrent.Name)
var selection string
for _, file := range torrent.SelectedFiles {
selection += fmt.Sprintf("%d,", file.ID)
@@ -594,20 +596,18 @@ func (t *TorrentManager) reinsertTorrent(torrent *Torrent, missingFiles string,
if len(selection) > 0 {
missingFiles = selection[:len(selection)-1]
}
} else {
log.Printf("Reinserting %d missing files for %s", len(strings.Split(missingFiles, ",")), torrent.Name)
}
// reinsert torrent
// redownload torrent
resp, err := realdebrid.AddMagnetHash(t.config.GetToken(), torrent.Hash)
if err != nil {
log.Printf("Cannot reinsert torrent: %v\n", err)
t.log.Errorf("Cannot redownload torrent: %v", err)
return false
}
newTorrentID := resp.ID
err = realdebrid.SelectTorrentFiles(t.config.GetToken(), newTorrentID, missingFiles)
if err != nil {
log.Printf("Cannot select files on reinserted torrent: %v\n", err)
t.log.Errorf("Cannot start redownloading: %v", err)
}
if deleteIfFailed {
@@ -619,7 +619,7 @@ func (t *TorrentManager) reinsertTorrent(torrent *Torrent, missingFiles string,
// see if the torrent is ready
info, err := realdebrid.GetTorrentInfo(t.config.GetToken(), newTorrentID)
if err != nil {
log.Printf("Cannot get info on reinserted torrent: %v\n", err)
t.log.Errorf("Cannot get info on redownloaded torrent: %v", err)
if deleteIfFailed {
realdebrid.DeleteTorrent(t.config.GetToken(), newTorrentID)
}
@@ -628,17 +628,17 @@ func (t *TorrentManager) reinsertTorrent(torrent *Torrent, missingFiles string,
time.Sleep(1 * time.Second)
if info.Progress != 100 {
log.Printf("Torrent is not cached anymore, %d%%\n", info.Progress)
t.log.Infof("Torrent is not cached anymore so we have to wait until completion, currently %d%%", info.Progress)
realdebrid.DeleteTorrent(t.config.GetToken(), newTorrentID)
return false
}
if len(info.Links) != len(torrent.SelectedFiles) {
log.Printf("It doesn't fix the problem, got %d links but we need %d\n", len(info.Links), len(torrent.SelectedFiles))
t.log.Infof("It didn't fix the issue, only got %d files but we need %d, undoing", len(info.Links), len(torrent.SelectedFiles))
realdebrid.DeleteTorrent(t.config.GetToken(), newTorrentID)
return false
}
log.Println("Reinsertion successful, deleting old torrent")
t.log.Info("Redownload successful, deleting old torrent")
realdebrid.DeleteTorrent(t.config.GetToken(), torrent.ID)
}
return true
@@ -713,9 +713,9 @@ func (t *TorrentManager) canCapacityHandle() bool {
for {
count, err := realdebrid.GetActiveTorrentCount(t.config.GetToken())
if err != nil {
log.Printf("Cannot get active torrent count: %v\n", err)
t.log.Errorf("Cannot get active downloads count: %v", err)
if retryCount >= maxRetries {
log.Println("Max retries reached. Exiting.")
t.log.Error("Max retries reached. Exiting.")
return false
}
delay := time.Duration(math.Pow(2, float64(retryCount))) * baseDelay
@@ -728,12 +728,12 @@ func (t *TorrentManager) canCapacityHandle() bool {
}
if count.DownloadingCount < count.MaxNumberOfTorrents {
log.Printf("We can still add a new torrent, %d/%d\n", count.DownloadingCount, count.MaxNumberOfTorrents)
t.log.Infof("We can still add a new torrent, we have capacity for %d more", count.MaxNumberOfTorrents-count.DownloadingCount)
return true
}
if retryCount >= maxRetries {
log.Println("Max retries reached. Exiting.")
t.log.Error("Max retries reached, exiting")
return false
}
delay := time.Duration(math.Pow(2, float64(retryCount))) * baseDelay