fix(lotw): show the download moving, retry a busy server, fail a dead one

Three reports of the same shape: a 503 for anything wider than a few days before, and since the timeout was raised, a window that sits at 'working' forever. Both are the same missing thing — nothing said what the transfer was doing. The body is now read in chunks and every megabyte is reported. A 503/502/504 is retried twice, 20 s then 40 s, each attempt announced: LoTW answers 'busy' to a wide report often enough that other loggers simply ask again. And the deadline is no longer on the whole exchange, which either cut off a healthy slow download or hid a dead one for twenty minutes — it is ten minutes to START answering (LoTW builds the whole report first) and two minutes of silence once it has, which is the difference between slow and dead.
2026-08-28 08:29:26 +02:00
parent 9a21c936b1
commit aec363b152
3 changed files with 118 additions and 13 deletions
@@ -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