diff --git a/app.go b/app.go index d7b4a2f..d6adcc9 100644 --- a/app.go +++ b/app.go @@ -12212,7 +12212,10 @@ func (a *App) runDownloadConfirmations(ctx context.Context, svc extsvc.Service, emit(fmt.Sprintf("Downloading all LoTW confirmations for %s…", callLabel)) } emit(fmt.Sprintf("Window: since=%q → resolved=%q (scope owncall=%q)", since, sinceDate, ownCall)) - adifText, err := extsvc.DownloadLoTWConfirmations(ctx, nil, cfg.LoTW, sinceDate, ownCall) + // The report arrives over minutes, and a window that says nothing while it + // does is indistinguishable from one that has hung — which is what it was + // being reported as. Every half-megabyte, say how much has landed. + adifText, err := extsvc.DownloadLoTWConfirmations(ctx, nil, cfg.LoTW, sinceDate, ownCall, emit) if err != nil { emit("Download failed: " + err.Error()) done(matched, total) diff --git a/changelog.json b/changelog.json index 5637b35..c46fcd9 100644 --- a/changelog.json +++ b/changelog.json @@ -12,7 +12,8 @@ "QSL Manager: a QRZ button next to the Paper QSL search, opening the callsign on QRZ.com.", "LoTW: an \"All my callsigns\" option beside the download. The download is scoped to the profile’s own callsign, so a QSO made as a portable or contest call was confirmed at LoTW and never marked here. Confirmations made under a callsign this logbook has never used are skipped, and a suspiciously small report now shows what LoTW actually answered.", "LoTW download: \"All\" really means all — without a date LoTW answered with a handful of recent confirmations, which looked like a successful download of an empty account. A full account also has time to arrive: the two-minute limit that ended in \"context deadline exceeded\" is now twenty.", - "Distances can be shown in miles (Settings → General): the cluster and Recent QSOs columns, the map path box, the rotator buttons and the band-opening list all follow, and the column headers name the unit." + "Distances can be shown in miles (Settings → General): the cluster and Recent QSOs columns, the map path box, the rotator buttons and the band-opening list all follow, and the column headers name the unit.", + "LoTW download: the report is now counted in megabytes as it arrives, LoTW’s \"busy\" answer (HTTP 503) is retried twice instead of failing, and a transfer that stops moving for two minutes says so rather than showing \"working\" indefinitely." ], "fr": [ "Chaque radio porte son propre MY_RIG (Réglages → CAT), inscrit sur chaque QSO fait avec elle — avant la station par bande des Conditions de trafic, qui dit ce qui était prévu et non quelle radio émet. Laissé vide, rien ne change.", @@ -24,7 +25,8 @@ "Gestionnaire QSL : un bouton QRZ à côté de la recherche QSL papier, qui ouvre l'indicatif sur QRZ.com.", "LoTW : une option « Tous mes indicatifs » à côté du téléchargement. Celui-ci est limité à l'indicatif du profil, si bien qu'un QSO fait sous un indicatif portable ou de contest était confirmé chez LoTW sans jamais être marqué ici. Les confirmations faites sous un indicatif que ce carnet n'a jamais utilisé sont ignorées, et un rapport anormalement petit affiche désormais ce que LoTW a réellement répondu.", "Téléchargement LoTW : « Tout » veut enfin dire tout — sans date, LoTW ne renvoyait qu'une poignée de confirmations récentes, ce qui ressemblait à un téléchargement réussi d'un compte vide. Un compte complet a aussi le temps d'arriver : la limite de deux minutes, qui finissait en « context deadline exceeded », passe à vingt.", - "Les distances peuvent s'afficher en miles (Réglages → Général) : les colonnes du cluster et des QSO récents, l'encart du tracé sur la carte, les boutons du rotor et la liste des ouvertures suivent, et l'unité est indiquée dans les en-têtes de colonne." + "Les distances peuvent s'afficher en miles (Réglages → Général) : les colonnes du cluster et des QSO récents, l'encart du tracé sur la carte, les boutons du rotor et la liste des ouvertures suivent, et l'unité est indiquée dans les en-têtes de colonne.", + "Téléchargement LoTW : le rapport est compté en mégaoctets au fur et à mesure, la réponse « occupé » de LoTW (HTTP 503) est retentée deux fois au lieu d'échouer, et un transfert qui n'avance plus pendant deux minutes le dit au lieu d'afficher « en cours » indéfiniment." ] }, { diff --git a/internal/extsvc/lotw.go b/internal/extsvc/lotw.go index 0f36780..7bf62c3 100644 --- a/internal/extsvc/lotw.go +++ b/internal/extsvc/lotw.go @@ -20,6 +20,67 @@ import ( // document of the user's QSOs (optionally only confirmed ones). const lotwReportURL = "https://lotw.arrl.org/lotwuser/lotwreport.adi" +const ( + // How long LoTW may take to START answering. It builds the whole report + // before sending anything, so this is the slow part of a big account. + lotwHeaderTimeout = 10 * time.Minute + // How long the transfer may stall once it HAS started. A download that has + // not moved in this long is not slow, it is dead — and saying so beats a + // progress window that sits at "working" until someone gives up. + lotwIdleTimeout = 2 * time.Minute + lotwMaxBytes = 256 * 1024 * 1024 +) + +// readWithProgress reads the body in chunks, reporting the running total and +// failing fast on a stall. +// +// Reported as it arrives rather than at the end: an 18 MB report over a slow +// link is minutes of silence otherwise, which is indistinguishable from a hang — +// and that is exactly what operators were reporting. +func say(note func(string), msg string) { + if note != nil { + note(msg) + } + LogSink("%s", msg) +} + +func readWithProgress(ctx context.Context, r io.Reader, note func(string)) ([]byte, error) { + var ( + out []byte + total int64 + last = time.Now() + buf = make([]byte, 64*1024) + next = int64(1024 * 1024) // first report at 1 MB + ) + for { + if err := ctx.Err(); err != nil { + return nil, err + } + n, err := r.Read(buf) + if n > 0 { + out = append(out, buf[:n]...) + total += int64(n) + last = time.Now() + if total >= next { + say(note, fmt.Sprintf(" … %.1f MB received", float64(total)/(1024*1024))) + next = total + 1024*1024 + } + if total >= lotwMaxBytes { + return out, nil + } + } + if err == io.EOF { + return out, nil + } + if err != nil { + return nil, err + } + if time.Since(last) > lotwIdleTimeout { + return nil, fmt.Errorf("the transfer stalled after %d KB — LoTW stopped sending", total/1024) + } + } +} + // DownloadLoTWConfirmations fetches confirmed QSOs from LoTW as ADIF text. // Uses the LoTW *website* login (Username/Password), not the TQSL cert. When // since is non-empty (YYYY-MM-DD) only confirmations received since then are @@ -27,7 +88,7 @@ const lotwReportURL = "https://lotw.arrl.org/lotwuser/lotwreport.adi" // non-empty, only confirmations for that station callsign are returned (an // LoTW account holds every call you operate — F4BPO, F4BPO/P, TM2Q — so this // scopes the pull to the active profile's call). -func DownloadLoTWConfirmations(ctx context.Context, client *http.Client, cfg ServiceConfig, since, ownCall string) (string, error) { +func DownloadLoTWConfirmations(ctx context.Context, client *http.Client, cfg ServiceConfig, since, ownCall string, note func(string)) (string, error) { user := strings.TrimSpace(cfg.Username) if user == "" || cfg.Password == "" { return "", fmt.Errorf("lotw: website login (username/password) not set") @@ -57,20 +118,59 @@ func DownloadLoTWConfirmations(ctx context.Context, client *http.Client, cfg Ser if err != nil { return "", fmt.Errorf("lotw: build request: %w", err) } + // Named, because LoTW's front end throttles unidentified clients harder than + // it throttles known ones, and an operator reporting a 503 deserves a request + // that says who is asking. + req.Header.Set("User-Agent", "OpsLog") if client == nil { - // A full account is tens of megabytes and LoTW builds it slowly — several - // minutes for a log of 30 000 QSOs, all of it before the first byte. The - // old two-minute limit turned that into "context deadline exceeded while - // reading body", which reads as a network fault rather than as "ask for - // less at a time". - client = &http.Client{Timeout: 20 * time.Minute} + // NO overall deadline. A full account is tens of megabytes and LoTW spends + // minutes building it before the first byte; a total timeout turns a slow + // but healthy download into "context deadline exceeded", and a longer one + // turns a dead connection into a window that says "working" for twenty + // minutes. What matters is not how long it takes but whether it is still + // moving — see the idle watchdog below. + client = &http.Client{ + Transport: &http.Transport{ + Proxy: http.ProxyFromEnvironment, + ResponseHeaderTimeout: lotwHeaderTimeout, + TLSHandshakeTimeout: 30 * time.Second, + }, + } + } + // LoTW answers 503 when it is busy, which for a report covering more than a + // few days is often — other loggers get the same answer and simply ask + // again. Three tries, spaced, and each one said out loud: an operator whose + // download takes four minutes because the ARRL is loaded should be able to + // see that rather than guess it. + var resp *http.Response + for attempt := 1; ; attempt++ { + resp, err = client.Do(req) //nolint:bodyclose // closed below or in the retry + if err == nil && resp.StatusCode != http.StatusServiceUnavailable && + resp.StatusCode != http.StatusBadGateway && resp.StatusCode != http.StatusGatewayTimeout { + break + } + if attempt >= 3 { + break + } + wait := time.Duration(attempt*20) * time.Second + if resp != nil { + say(note, fmt.Sprintf("LoTW is busy (HTTP %d) — asking again in %s…", resp.StatusCode, wait)) + resp.Body.Close() + } else { + say(note, fmt.Sprintf("LoTW did not answer (%v) — asking again in %s…", err, wait)) + } + select { + case <-ctx.Done(): + return "", ctx.Err() + case <-time.After(wait): + } + req = req.Clone(ctx) } - resp, err := client.Do(req) if err != nil { return "", fmt.Errorf("lotw: request failed: %w", err) } defer resp.Body.Close() - body, err := io.ReadAll(io.LimitReader(resp.Body, 256*1024*1024)) + body, err := readWithProgress(ctx, resp.Body, note) if err != nil { return "", fmt.Errorf("lotw: read response: %w", err) } @@ -378,7 +478,7 @@ func TestLoTW(cfg ServiceConfig, stationDataPath string) (string, error) { } ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() - if _, err := DownloadLoTWConfirmations(ctx, nil, cfg, "2099-01-01", ""); err != nil { + if _, err := DownloadLoTWConfirmations(ctx, nil, cfg, "2099-01-01", "", nil); err != nil { return "", fmt.Errorf("%s — but the DOWNLOAD login failed: %w", up, err) } return up + ". Download login accepted.", nil