diff --git a/app.go b/app.go index 369277a..7b4bb2b 100644 --- a/app.go +++ b/app.go @@ -10376,6 +10376,15 @@ func (a *App) TestCloudlogUpload() (string, error) { // ── QSL Manager (manual upload) ──────────────────────────────────────── // uploadColumnFor maps a service id to its QSO sent-status column. +// manualUploadPace is the shortest gap between two consecutive single-QSO +// uploads in a bulk "Send to …" run, for the services with no batch endpoint +// (QRZ.com, HRDLog). Selecting twenty-five thousand QSOs in the QSL Manager and +// firing them off as fast as the link allows is exactly the traffic a logbook +// service reads as a robot rather than an operator — Club Log threatens to block +// an IP for it. The gap is free in practice: a round trip to either already +// takes longer than it. +const manualUploadPace = 200 * time.Millisecond + func uploadColumnFor(service string) string { switch extsvc.Service(service) { case extsvc.ServiceQRZ: @@ -10470,10 +10479,13 @@ func (a *App) runManualUpload(svc extsvc.Service, ids []int64, cfg extsvc.Extern } } } - } else if svc == extsvc.ServiceClublog || svc == extsvc.ServiceHRDLog { + } else if svc == extsvc.ServiceClublog || svc == extsvc.ServiceHRDLog || svc == extsvc.ServiceEQSL { statusCol, dateCol := "clublog_qso_upload_status", "clublog_qso_upload_date" - if svc == extsvc.ServiceHRDLog { + switch svc { + case extsvc.ServiceHRDLog: statusCol, dateCol = "hrdlog_qso_upload_status", "hrdlog_qso_upload_date" + case extsvc.ServiceEQSL: + statusCol, dateCol = "eqsl_sent", "eqsl_sent_date" } type item struct { id int64 @@ -10537,10 +10549,62 @@ func (a *App) runManualUpload(svc extsvc.Service, ids []int64, cfg extsvc.Extern applog.Printf("extsvc: Club Log batch FAILED (%s) — QSOs: %s", msg, strings.Join(who, ", ")) } } + } else if svc == extsvc.ServiceEQSL { + // eQSL's ImportADIF.cfm is a file importer — it answers "X out of Y + // records added" — so send a whole chunk per request instead of one + // request per contact. eQSL asks that an upload stay under about a + // thousand records; 100 keeps a single refused record from taking the + // rest of the chunk with it. + const chunk = 100 + emit(fmt.Sprintf("eQSL: uploading %d QSO(s) in batches of %d…", len(items), chunk)) + for start := 0; start < len(items); start += chunk { + end := start + chunk + if end > len(items) { + end = len(items) + } + batch := items[start:end] + recs := make([]string, len(batch)) + batchIDs := make([]int64, len(batch)) + for i, it := range batch { + recs[i] = it.rec + batchIDs[i] = it.id + } + res, err := extsvc.UploadEQSLBatch(ctx, nil, cfg.EQSL.Username, cfg.EQSL.Password, cfg.EQSL.QTHNickname, recs) + if err == nil && res.OK { + if merr := a.qso.MarkUploadedBatch(ctx, statusCol, dateCol, date, batchIDs); merr != nil { + applog.Printf("extsvc: eQSL batch mark: %v", merr) + } + uploaded += len(batch) + // eQSL took the file but left records out. It never says WHICH + // — normally they are QSOs it already holds — so quote its own + // count rather than claim a clean run. + if res.Ignored { + emit(fmt.Sprintf("eQSL: %d/%d uploaded — %s", end, len(items), res.Message)) + } else { + emit(fmt.Sprintf("eQSL: %d/%d uploaded", end, len(items))) + } + } else { + msg := res.Message + if err != nil { + msg = err.Error() + } + // Name the QSOs in the failing batch, same as Club Log: a + // per-record rejection is otherwise impossible to locate. + who := make([]string, 0, len(batch)) + for _, it := range batch { + who = append(who, fmt.Sprintf("%s#%d", it.call, it.id)) + } + emit(fmt.Sprintf("eQSL: batch of %d FAILED: %s", len(batch), msg)) + applog.Printf("extsvc: eQSL batch FAILED (%s) — QSOs: %s", msg, strings.Join(who, ", ")) + } + } } else { // HRDLog's NewEntry.aspx inserts only the FIRST record of a multi- // record ADIF, so upload ONE record per request. The DB stays cheap: // bulk fetch above + the marks flushed in batches (not one per QSO). + // Paced: HRDLog is the one service here with no way to batch, and a + // few thousand requests as fast as the link allows is what a logbook + // reads as a robot. emit(fmt.Sprintf("HRDLog: uploading %d QSO(s) (one request each)…", len(items))) var doneIDs []int64 flush := func() { @@ -10553,6 +10617,9 @@ func (a *App) runManualUpload(svc extsvc.Service, ids []int64, cfg extsvc.Extern doneIDs = doneIDs[:0] } for i, it := range items { + if i > 0 { + time.Sleep(manualUploadPace) + } res, err := extsvc.UploadHRDLog(ctx, nil, cfg.HRDLog.Callsign, cfg.HRDLog.Code, it.rec) if err == nil && res.OK { doneIDs = append(doneIDs, it.id) @@ -10574,34 +10641,26 @@ func (a *App) runManualUpload(svc extsvc.Service, ids []int64, cfg extsvc.Extern flush() } } else { - // QRZ.com: one record per request (its logbook API has no batch upload). - for _, id := range ids { + // QRZ.com: one record per request (its logbook API has no batch upload), + // paced for the same reason as HRDLog above. + for i, id := range ids { + if i > 0 { + time.Sleep(manualUploadPace) + } q, gerr := a.qso.GetByID(ctx, id) call := "" if gerr == nil { call = q.Callsign } - force := "" - if svc == extsvc.ServiceQRZ { - force = cfg.QRZ.ForceStationCallsign - } - rec, ok := a.buildUploadADIF(id, force) + // QRZ rewrites STATION_CALLSIGN to the registered call. + rec, ok := a.buildUploadADIF(id, cfg.QRZ.ForceStationCallsign) if !ok { emit(call + " — skipped (no record)") continue } - var res extsvc.UploadResult - var err error - switch svc { - case extsvc.ServiceQRZ: - res, err = extsvc.UploadQRZ(ctx, nil, cfg.QRZ.APIKey, rec) - case extsvc.ServiceHRDLog: - res, err = extsvc.UploadHRDLog(ctx, nil, cfg.HRDLog.Callsign, cfg.HRDLog.Code, rec) - case extsvc.ServiceEQSL: - res, err = extsvc.UploadEQSL(ctx, nil, cfg.EQSL.Username, cfg.EQSL.Password, cfg.EQSL.QTHNickname, rec) - default: - res, err = extsvc.UploadClublog(ctx, nil, cfg.Clublog, rec) - } + // Only QRZ reaches this branch: LoTW, Club Log, HRDLog and eQSL are + // all handled above, and UploadQSOsManual rejects anything else. + res, err := extsvc.UploadQRZ(ctx, nil, cfg.QRZ.APIKey, rec) if err == nil && res.OK { a.markExtUploaded(svc, id, "") uploaded++ @@ -17713,16 +17772,26 @@ func (a *App) SendClusterCommand(cmd string) error { if cmd == "" { return fmt.Errorf("empty command") } - servers, err := a.listClusterServers() + srv, err := a.masterClusterServer() if err != nil { return err } + return a.cluster.SendCommand(srv.ID, cmd) +} + +// masterClusterServer returns the master node — the first ENABLED server in +// sort order, which is where commands and spots go. +func (a *App) masterClusterServer() (cluster.ServerConfig, error) { + servers, err := a.listClusterServers() + if err != nil { + return cluster.ServerConfig{}, err + } for _, s := range servers { if s.Enabled { - return a.cluster.SendCommand(s.ID, cmd) + return s, nil } } - return fmt.Errorf("no enabled cluster server to send to") + return cluster.ServerConfig{}, fmt.Errorf("no enabled cluster server to send to") } // SendClusterSpot announces a DX spot on the **master** cluster (first @@ -17744,8 +17813,26 @@ func (a *App) SendClusterSpot(call string, freqKHz float64, comment string) erro if c := strings.TrimSpace(comment); c != "" { cmd += " " + c } + if a.cluster == nil { + return fmt.Errorf("cluster not initialized") + } + srv, err := a.masterClusterServer() + if err != nil { + return err + } applog.Printf("cluster: send spot — freqKHz=%v → command %q", freqKHz, cmd) - return a.SendClusterCommand(cmd) + if err := a.cluster.SendCommand(srv.ID, cmd); err != nil { + return err + } + // Show it in OUR OWN spot list straight away. Most nodes never broadcast a + // spot back to the station that sent it, so the operator saw nothing appear + // and reported the spot as not sent — several times. It goes through the same + // queue as a spot off the wire, so it gets the same DXCC/POTA enrichment, + // alert evaluation and panadapter mirroring, and the UI de-dupes it against + // the node's echo when there is one. + sp := cluster.NewLocalSpot(srv, a.resolveClusterLogin(srv.LoginOverride), call, freqKHz, comment) + a.enqueueClusterEvent(clusterEvent{spot: &sp}) + return nil } // GetClusterStatus returns a snapshot of every active session. Used by diff --git a/changelog.json b/changelog.json index c6b9368..84c4458 100644 --- a/changelog.json +++ b/changelog.json @@ -11,7 +11,12 @@ "Award references can be renumbered in the editor — the number was the one field it would not let you correct.", "The compass fills the moment Station Control opens, instead of waiting out the rest of a polling interval.", "Combined amplifiers: the power level (L/M/H) is coupled too, and both amps are commanded at once so the combiner stops beeping.", - "Generic HTTP relay: an https:// board can be accepted with its own self-signed certificate, per board." + "Generic HTTP relay: an https:// board can be accepted with its own self-signed certificate, per board.", + "Club Log: the on-close upload now goes out as one batch — sending hundreds of contacts one at a time got operators blocked.", + "eQSL: uploads go out in batches of 100 too, and QRZ.com and HRDLog — which have no batch upload — are spaced out instead.", + "A spot you send now shows in your own spot list — most nodes never echo it back, so it looked like nothing had gone out.", + "Icom with JTDX in Fake It split: a lost PTT acknowledgement is sent again instead of failing, which made JTDX drop the rig.", + "A cluster whose only greeting is “login:” and which then asks for a password now connects — both prompts were being missed." ], "fr": [ "Une entité qui est un seul groupe d’îles remplit désormais la référence IOTA toute seule, sans abonnement callbook.", @@ -22,7 +27,12 @@ "Les références d’un diplôme se renumérotent dans l’éditeur : le numéro était le seul champ qu’il refusait de corriger.", "La boussole se remplit dès l’ouverture de Station Control, au lieu d’attendre la fin d’un intervalle d’interrogation.", "Amplis combinés : le niveau de puissance (L/M/H) est couplé lui aussi, et les deux amplis sont commandés en même temps — fini le bip du combineur.", - "Relais HTTP générique : une carte en https:// peut être acceptée avec son certificat auto-signé, carte par carte." + "Relais HTTP générique : une carte en https:// peut être acceptée avec son certificat auto-signé, carte par carte.", + "Club Log : l’envoi à la fermeture part désormais en un lot — envoyer des centaines de contacts un par un faisait bloquer l’opérateur.", + "eQSL : les envois partent aussi par lots de 100, et QRZ.com et HRDLog — qui n’ont pas d’envoi groupé — sont espacés à la place.", + "Un spot que tu envoies apparaît maintenant dans ta liste : la plupart des nœuds ne le renvoient pas, il semblait n’être jamais parti.", + "Icom avec JTDX en split Fake It : un accusé de réception PTT perdu est renvoyé au lieu d’échouer — JTDX lâchait le poste.", + "Un cluster dont tout l’accueil est « login: » puis qui réclame un mot de passe se connecte : les deux invites étaient ignorées." ] }, { diff --git a/frontend/src/version.ts b/frontend/src/version.ts index c726930..bbcdeb4 100644 --- a/frontend/src/version.ts +++ b/frontend/src/version.ts @@ -1,6 +1,6 @@ // Single source of truth for the app version shown in the UI (header + About). // Bump this on a release (the release script updates it alongside telemetry.go). -export const APP_VERSION = '0.25.7'; +export const APP_VERSION = '0.25.8'; // Author / credits, shown in Help -> About. export const APP_AUTHOR = 'F4BPO'; diff --git a/internal/cat/icomserial.go b/internal/cat/icomserial.go index 73b1d2d..ae29a47 100644 --- a/internal/cat/icomserial.go +++ b/internal/cat/icomserial.go @@ -1,6 +1,7 @@ package cat import ( + "errors" "fmt" "strings" "sync" @@ -535,11 +536,36 @@ func (b *IcomSerial) SetMode(mode string) error { return nil } +// errIcomAckLost is "the reply never came" — as opposed to a reply that said no +// (NG) or a dead port. Only this one is worth repeating: the command may well +// have been carried out and only its acknowledgement lost. Sentinel rather than +// a formatted string so callers can tell the two apart. +var errIcomAckLost = errors.New("icom: timeout waiting for response") + +// SetPTT keys or unkeys the transmitter (CI-V 0x1C 0x00), retrying ONCE when the +// acknowledgement is lost. +// +// A missing FB is not a missing command — the rig acts on the frame as soon as it +// decodes it, and what expires is our wait for the answer on a bus shared with +// the rig's own transceive updates. JTDX in "Split Operating: Fake It" moves the +// dial immediately before every key-down, so the PTT ack queues behind that +// traffic, and one lost ack was fatal: rigctld answered RPRT -9, JTDX read that +// as losing rig control and tore the connection down mid-over, reopening it a +// moment later (an operator's log shows exactly that, twice, a new rigctld client +// within 300 ms of each failure). The same session over TCI never failed, because +// TCI carries no CI-V and needs no Fake It. +// +// Re-sending is safe: asking for a state the rig is already in changes nothing. func (b *IcomSerial) SetPTT(on bool) error { state := byte(0) if on { state = 1 } + err := b.exec(civ.CmdPTT, civ.SubPTT, state) + if err == nil || !errors.Is(err, errIcomAckLost) { + return err + } + applog.Printf("icom: PTT %v — no acknowledgement in %s, sending it once more", on, icomCmdTimeout) return b.exec(civ.CmdPTT, civ.SubPTT, state) } @@ -619,7 +645,7 @@ func (b *IcomSerial) recv(timeout time.Duration, match func(civ.Decoded) bool) ( case <-cancel: return civ.Decoded{}, fmt.Errorf("icom: interrupted") case <-deadline: - return civ.Decoded{}, fmt.Errorf("icom: timeout waiting for response") + return civ.Decoded{}, errIcomAckLost } } } diff --git a/internal/cluster/cluster.go b/internal/cluster/cluster.go index dc19c37..eb23ad8 100644 --- a/internal/cluster/cluster.go +++ b/internal/cluster/cluster.go @@ -18,6 +18,7 @@ import ( "strconv" "strings" "sync" + "sync/atomic" "time" "hamlog/internal/applog" @@ -355,6 +356,18 @@ func (s *session) run() { // that gets skipped. var idleTick = 30 * time.Second +// promptTick is the read deadline used until the login handshake is finished. +// Short, because a node's "login:" / "password:" carries no newline and is only +// visible when the read times out — see the read loop. It costs a few wake-ups +// during the first seconds of a connection and nothing afterwards. +const promptTick = 700 * time.Millisecond + +// handshakeWindow bounds how long the fast promptTick applies. A node that has +// a password configured but never asks for one would otherwise keep the loop +// waking every 700 ms for the life of the connection, for a prompt that is never +// coming. Any real login exchange is over in a second or two. +const handshakeWindow = 20 * time.Second + // quietNotice is the silence after which the log says so, once. const quietNotice = 10 * time.Minute @@ -398,16 +411,37 @@ func (s *session) runOnce() (time.Time, error) { // Login: send on first prompt OR blindly after 1.5s. Many DXSpider // nodes accept the callsign without re-prompting. - loginSent := false + // + // Atomic because the blind-login timer below and the read loop both touch + // these. loginSent used to be a plain bool that the timer NEVER SET: the + // callsign went out and nothing recorded it, so the password branch — gated on + // loginSent — was dead code, and the session could only reach "connected" by + // recognising a welcome banner. On a node whose entire greeting is a bare + // "login:" and which then demands a password (f5mzn.org:9000), that left the + // server stuck at "connecting" for ever while telnet logged in by hand fine. + var loginSent, pwdSent atomic.Bool + // CompareAndSwap, not a plain store: the timer and the loop can reach these at + // the same moment, and the callsign must be written exactly once. + sendLogin := func() { + if s.login != "" && loginSent.CompareAndSwap(false, true) { + _, _ = conn.Write([]byte(s.login + "\r\n")) + } + } + // Sent ONCE per connection. A node that re-prompts is refusing the password, + // and answering with the same one again only loops — better to let the + // refusal show in the console than to hide it behind a retry. + sendPassword := func() { + if s.cfg.Password != "" && loginSent.Load() && pwdSent.CompareAndSwap(false, true) { + _, _ = conn.Write([]byte(s.cfg.Password + "\r\n")) + } + } if s.login != "" { go func() { select { case <-s.stopCh: return case <-time.After(1500 * time.Millisecond): - if !loginSent { - _, _ = conn.Write([]byte(s.login + "\r\n")) - } + sendLogin() } }() } @@ -453,7 +487,21 @@ func (s *session) runOnce() (time.Time, error) { var connectedAt time.Time var quiet time.Duration // how long the node has said nothing + var quietNoticed bool // the long-silence line is said once var pending string // a line cut in half by a read deadline + markConnected := func() { + if s.snapshot().State == StateConnected { + return + } + connectedAt = time.Now() + s.mu.Lock() + s.status.State = StateConnected + s.status.ConnectedAt = connectedAt + s.status.Error = "" + s.mu.Unlock() + s.emitStatus() + fireInitCommands() + } rd := bufio.NewReader(conn) for { select { @@ -471,7 +519,21 @@ func (s *session) runOnce() (time.Time, error) { // Only a REAL error ends the session. A dead peer still gets caught: // TCP keepalive probes an idle connection and its failure arrives here // as an error, not as a timeout. - _ = conn.SetReadDeadline(time.Now().Add(idleTick)) + // SHORT deadline until the handshake is done, the long idle tick after. + // + // A cluster writes its prompts WITHOUT a trailing newline, and ReadString + // only returns on one — so a prompt is never a "line" at all, it is whatever + // is sitting in the buffer when the read deadline expires. At the ordinary + // 30 s tick that made a bare "login:" invisible for half a minute and a + // following "password:" invisible for another, which is long enough for the + // node to give up on us. Only the handshake needs the fast tick; once logged + // in, a long deadline is exactly what we want (see idleTick). + tick := idleTick + if time.Since(linkUpAt) < handshakeWindow && + (!loginSent.Load() || (s.cfg.Password != "" && !pwdSent.Load())) { + tick = promptTick + } + _ = conn.SetReadDeadline(time.Now().Add(tick)) chunk, err := rd.ReadString('\n') if err != nil { var ne net.Error @@ -480,16 +542,48 @@ func (s *session) runOnce() (time.Time, error) { // Keep it: a spot line straddling the deadline would otherwise lose // its first half and arrive as nonsense, or vanish entirely. pending += chunk - quiet += idleTick + // …but a newline-less PROMPT is not half a line, it is a question, + // and this is the only place it can ever be seen. Answer it, show it + // in the console (an operator watching a stuck server has a right to + // see what the node actually asked), and drop it so it is not glued + // onto the front of the next real line. + if p := strings.TrimSpace(pending); p != "" { + switch { + case !loginSent.Load() && s.login != "" && isLoginPrompt(p): + s.emitLine(p, false) + pending = "" + sendLogin() + if s.cfg.Password == "" { + markConnected() + } + continue + case !pwdSent.Load() && isPasswordPrompt(p): + s.emitLine(p, false) + pending = "" + if s.cfg.Password == "" { + // Nothing to answer with. Shown in the console rather than + // swallowed: an unanswered "password:" sitting there IS the + // explanation for a server that never finishes connecting, + // and it is something the operator can act on. + continue + } + sendPassword() + markConnected() + continue + } + } + quiet += tick // Said once at the first long silence, so a genuinely mute node is // visible without a line every tick. - if quiet == quietNotice { + if !quietNoticed && quiet >= quietNotice { + quietNoticed = true applog.Printf("cluster[%s] no traffic for %s — still connected", s.cfg.Name, quiet) } continue } return connectedAt, fmt.Errorf("read: %w", err) } + quietNoticed = false quiet = 0 line := pending + chunk pending = "" @@ -519,28 +613,23 @@ func (s *session) runOnce() (time.Time, error) { } } - // Login on explicit prompt. - if !loginSent && s.login != "" && isLoginPrompt(line) { - _, _ = conn.Write([]byte(s.login + "\r\n")) - loginSent = true + // Login on explicit prompt — the case where the node DID terminate it with + // a newline. The newline-less form is handled on the timeout path above. + if !loginSent.Load() && s.login != "" && isLoginPrompt(line) { + s.emitLine(line, false) + sendLogin() continue } - // Password on prompt (rare). - if loginSent && s.cfg.Password != "" && isPasswordPrompt(line) { - _, _ = conn.Write([]byte(s.cfg.Password + "\r\n")) + // Password on prompt. + if !pwdSent.Load() && isPasswordPrompt(line) { + s.emitLine(line, false) + sendPassword() continue } // Mark connected once we've sent login OR seen a welcome banner. - if s.snapshot().State != StateConnected && (loginSent || isWelcome(line)) { - connectedAt = time.Now() - s.mu.Lock() - s.status.State = StateConnected - s.status.ConnectedAt = connectedAt - s.status.Error = "" - s.mu.Unlock() - s.emitStatus() - fireInitCommands() + if loginSent.Load() || isWelcome(line) { + markConnected() } // EVERY line goes to the console — spot or not. This is the whole point: @@ -701,6 +790,38 @@ func parseSpot(line string) (Spot, bool) { }, true } +// NewLocalSpot builds the Spot for a DX announcement WE just sent, so it lands +// in the operator's own list at once. +// +// A node does not necessarily broadcast a spot back to the station that sent it: +// DXSpider suppresses the echo to the originator, and a node-side filter can eat +// it too. So an operator spotted a station, watched their own spot list stay +// empty, and concluded the spot had never gone out — when it had. This is the +// spot the echo would have carried, built from what we sent, deliberately the +// same shape so the UI's call+band de-dupe folds the two into one row on the +// nodes that DO echo. +func NewLocalSpot(srv ServerConfig, spotter, dxCall string, freqKHz float64, comment string) Spot { + freqHz := int64(freqKHz*1000 + 0.5) + now := time.Now() + sp := Spot{ + SourceID: srv.ID, + SourceName: srv.Name, + Spotter: strings.ToUpper(strings.TrimSpace(spotter)), + DXCall: strings.ToUpper(strings.TrimSpace(dxCall)), + FreqKHz: freqKHz, + FreqHz: freqHz, + Band: bandFromHz(freqHz), + Comment: strings.TrimSpace(comment), + TimeUTC: now.UTC().Format("1504") + "Z", + ReceivedAt: now, + } + // Raw reads like the node's own broadcast — it is what anything showing the + // source line expects, and it keeps a local spot legible in the log. + sp.Raw = fmt.Sprintf("DX de %s: %9.1f %-12s %-30s %s", + sp.Spotter, sp.FreqKHz, sp.DXCall, sp.Comment, sp.TimeUTC) + return sp +} + func isLoginPrompt(s string) bool { low := strings.ToLower(s) return strings.Contains(low, "login:") || diff --git a/internal/cluster/login_test.go b/internal/cluster/login_test.go new file mode 100644 index 0000000..267c760 --- /dev/null +++ b/internal/cluster/login_test.go @@ -0,0 +1,105 @@ +package cluster + +import ( + "bufio" + "net" + "strconv" + "strings" + "testing" + "time" +) + +// A node whose whole greeting is a bare "login:" — no newline, no banner — and +// which then demands a password must still log in. +// +// Reported on f5mzn.org:9000: telnet by hand worked, OpsLog sat at "connecting" +// for ever. Two faults met there. The prompts carry no newline, and the read +// loop only ever looked at complete LINES, so neither prompt was seen at all; +// and the blind 1.5 s login never recorded that it had sent the callsign, which +// left the password branch — gated on that flag — permanently switched off. +// +// The test speaks the node's side literally: "login:" with no newline, then +// "password:" with no newline, then a spot. It asserts both answers arrive and +// that the session reaches Connected without any welcome banner to lean on. +func TestBareLoginAndPasswordPromptsWithoutNewlines(t *testing.T) { + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + defer ln.Close() + + host, portStr, _ := net.SplitHostPort(ln.Addr().String()) + port, err := strconv.Atoi(portStr) + if err != nil { + t.Fatal(err) + } + + type answers struct{ login, pwd string } + got := make(chan answers, 1) + go func() { + c, err := ln.Accept() + if err != nil { + return + } + defer c.Close() + rd := bufio.NewReader(c) + // No newline, exactly as the node sends it. + if _, err := c.Write([]byte("login: ")); err != nil { + return + } + call, err := rd.ReadString('\n') + if err != nil { + return + } + if _, err := c.Write([]byte("password: ")); err != nil { + return + } + pwd, err := rd.ReadString('\n') + if err != nil { + return + } + got <- answers{strings.TrimSpace(call), strings.TrimSpace(pwd)} + // Something to prove the link is live and parsing again afterwards. + _, _ = c.Write([]byte("DX de F4BPO: 14074.0 OY1CT FT8 1234Z\r\n")) + time.Sleep(time.Second) + }() + + spots := make(chan Spot, 4) + s := &session{ + cfg: ServerConfig{Name: "pwd node", Host: host, Port: port, Password: "s3cret"}, + login: "F4BPO", + onSpot: func(sp Spot) { spots <- sp }, + onLine: func(Line) {}, + onStatus: func() {}, + stopCh: make(chan struct{}), + } + done := make(chan error, 1) + go func() { _, err := s.runOnce(); done <- err }() + defer func() { close(s.stopCh); <-done }() + + select { + case a := <-got: + if a.login != "F4BPO" { + t.Errorf("callsign sent = %q, want F4BPO", a.login) + } + if a.pwd != "s3cret" { + t.Errorf("password sent = %q, want s3cret — the prompt carried no newline", a.pwd) + } + case <-time.After(10 * time.Second): + t.Fatal("the node's newline-less prompts were never answered") + } + + select { + case sp := <-spots: + if sp.DXCall != "OY1CT" { + t.Errorf("spot from the wrong station: %+v", sp) + } + case <-time.After(5 * time.Second): + t.Fatal("no spot after the login — the stream is not being parsed") + } + + // Connected without a welcome banner: the handshake alone must be enough. + if st := s.snapshot().State; st != StateConnected { + t.Errorf("state = %q, want %q — the server would still show as connecting", st, StateConnected) + } +} diff --git a/internal/extsvc/clublog.go b/internal/extsvc/clublog.go index 66bce77..f7e5c7f 100644 --- a/internal/extsvc/clublog.go +++ b/internal/extsvc/clublog.go @@ -117,6 +117,13 @@ func UploadClublogADIF(ctx context.Context, client *http.Client, cfg ServiceConf if api == "" { api = clublogAppAPIKey } + // putlogs.php reads the upload as an ADIF *file*, so it needs a header. + // Callers that already build a full document (the QSL Manager) pass one; + // callers that only have -terminated records (the on-close flush) do + // not, and a headerless file is rejected. Same rule as the LoTW writer. + if !strings.Contains(strings.ToUpper(adifDoc), "") { + adifDoc = "OpsLog Club Log upload\nOpsLog \n" + adifDoc + } var buf bytes.Buffer mw := multipart.NewWriter(&buf) diff --git a/internal/extsvc/eqsl.go b/internal/extsvc/eqsl.go index ef84d9e..c0b7344 100644 --- a/internal/extsvc/eqsl.go +++ b/internal/extsvc/eqsl.go @@ -267,6 +267,78 @@ func UploadEQSL(ctx context.Context, client *http.Client, user, pswd, qthNick, a return UploadResult{OK: false, Message: reason}, fmt.Errorf("eqsl: upload failed: %s", reason) } +// eqslBatchMax is the largest number of records eQSL asks a single upload to +// carry ("upload only files smaller than about 1000 records at a time", eQSL's +// own ImportADIF interface notes). Callers chunk to this. +const eqslBatchMax = 1000 + +// UploadEQSLBatch pushes MANY ADIF records to eQSL.cc in ONE request. +// +// ImportADIF.cfm is a file importer, not a per-QSO endpoint: it takes one *or +// more* QSOs and answers "Result: X out of Y records added" — the plural in its +// own reply. So an on-close sweep or a bulk upload is one request, not one per +// contact. No ADIF header is prepended: the single-record path has always posted +// bare records and eQSL accepts them (per ADIF, a file starting with '<' +// has no header), and there is no reason to change what is known to work. +// +// A PARTIAL result ("97 out of 100") sets Ignored so the caller can say so. +// eQSL does not identify which records it left out, and in practice they are +// QSOs it already holds — the same duplicate that UploadEQSL reports as success. +func UploadEQSLBatch(ctx context.Context, client *http.Client, user, pswd, qthNick string, records []string) (UploadResult, error) { + user = strings.ToUpper(strings.TrimSpace(user)) + if user == "" { + return UploadResult{}, fmt.Errorf("eqsl: username (callsign) not set") + } + if strings.TrimSpace(pswd) == "" { + return UploadResult{}, fmt.Errorf("eqsl: password not set") + } + docs := make([]string, 0, len(records)) + for _, r := range records { + if strings.TrimSpace(r) == "" { + continue + } + docs = append(docs, eqslRecordWithNickname(strings.TrimRight(r, "\r\n"), qthNick)) + } + if len(docs) == 0 { + return UploadResult{}, fmt.Errorf("eqsl: empty adif batch") + } + if len(docs) > eqslBatchMax { + return UploadResult{}, fmt.Errorf("eqsl: batch of %d exceeds the %d-record limit", len(docs), eqslBatchMax) + } + + body, err := eqslPost(ctx, client, user, pswd, strings.Join(docs, "\n")) + if err != nil { + return UploadResult{OK: false, Message: body}, err + } + if reason := authErrEQSL(body); reason != "" { + return UploadResult{OK: false, Message: reason}, fmt.Errorf("eqsl: %s", reason) + } + + // The counted result is read FIRST here, unlike the single-record path: a + // batch reply routinely carries both "Result: 97 out of 100 records added" + // and a "Bad record: Duplicate" line for the other three, and matching the + // duplicate first would throw away the count that says the rest went in. + if m := eqslResultRe.FindStringSubmatch(body); m != nil { + added, _ := strconv.Atoi(m[1]) + total, _ := strconv.Atoi(m[2]) + if added >= 1 { + return UploadResult{OK: true, Message: strings.TrimSpace(m[0]), Ignored: added < total}, nil + } + // "0 out of N" — nothing added. A re-upload of QSOs eQSL already holds + // lands here, and that is not a failure. + if strings.Contains(strings.ToLower(body), "duplicate") { + return UploadResult{OK: true, Message: "already in logbook"}, nil + } + reason := eqslReason(body) + return UploadResult{OK: false, Message: reason}, fmt.Errorf("eqsl: batch upload failed: %s", reason) + } + if strings.Contains(strings.ToLower(body), "duplicate") { + return UploadResult{OK: true, Message: "already in logbook"}, nil + } + reason := eqslReason(body) + return UploadResult{OK: false, Message: reason}, fmt.Errorf("eqsl: batch upload failed: %s", reason) +} + // eqslReason trims an eQSL reply to a short human-readable reason: the first // "Error:" / "Warning:" / "Bad record:" line if present, else the whole body // (capped), else a generic phrase. diff --git a/internal/extsvc/manager.go b/internal/extsvc/manager.go index 107d921..ec67baa 100644 --- a/internal/extsvc/manager.go +++ b/internal/extsvc/manager.go @@ -295,9 +295,10 @@ func (m *Manager) CloseUploadCount() int { } // FlushOnClose uploads every QSO due for an on-close push, scanning the whole -// logbook (not just this session). Called from the shutdown sequence. QRZ/Club -// Log go one-by-one (fast HTTP); LoTW is signed and uploaded as a single TQSL -// batch. Returns the number of QSOs uploaded successfully. +// logbook (not just this session). Called from the shutdown sequence. QRZ and +// the rest go one-by-one (fast HTTP, no batch API); LoTW is signed and uploaded +// as a single TQSL batch, and Club Log goes through its batch endpoint. +// Returns the number of QSOs uploaded successfully. func (m *Manager) FlushOnClose() int { if m.deps.CloseUploadIDs == nil { return 0 @@ -312,41 +313,190 @@ func (m *Manager) FlushOnClose() int { switch svc { case ServiceLoTW: uploaded += m.flushLoTWBatch(ids, cfg.LoTW) - case ServiceQRZ: - for _, id := range ids { - if ok, _ := m.upload(svc, id, cfg.QRZ); ok { - uploaded++ - } - } case ServiceClublog: - for _, id := range ids { - if ok, _ := m.upload(svc, id, cfg.Clublog); ok { - uploaded++ - } - } - case ServiceHRDLog: - for _, id := range ids { - if ok, _ := m.upload(svc, id, cfg.HRDLog); ok { - uploaded++ - } - } + uploaded += m.flushClublogBatch(ids, cfg.Clublog) case ServiceEQSL: - for _, id := range ids { - if ok, _ := m.upload(svc, id, cfg.EQSL); ok { - uploaded++ - } - } + uploaded += m.flushEQSLBatch(ids, cfg.EQSL) + case ServiceQRZ: + uploaded += m.flushOneByOne(svc, ids, cfg.QRZ) + case ServiceHRDLog: + uploaded += m.flushOneByOne(svc, ids, cfg.HRDLog) case ServiceCloudlog: - for _, id := range ids { - if ok, _ := m.upload(svc, id, cfg.Cloudlog); ok { - uploaded++ - } - } + uploaded += m.flushOneByOne(svc, ids, cfg.Cloudlog) } } return uploaded } +// uploadPace is the shortest gap between two consecutive single-QSO uploads in +// an on-close sweep. QRZ, HRDLog and Cloudlog have no batch endpoint — HRDLog's +// NewEntry.aspx keeps only the first record of a multi-record ADIF — so a sweep +// of a freshly imported log is unavoidably one request per contact. It does not +// have to arrive as fast as the link allows, though: that burst is what a +// service reads as a robot, and what got an operator's IP threatened at Club Log +// (see flushClublogBatch). The gap costs nothing in practice, since a round trip +// to any of these already takes longer than it. +const uploadPace = 200 * time.Millisecond + +// flushOneByOne uploads ids one request at a time, paced. For the services that +// have no batch API; everything else has its own flushBatch. +func (m *Manager) flushOneByOne(svc Service, ids []int64, cfg ServiceConfig) int { + uploaded := 0 + for i, id := range ids { + if i > 0 { + time.Sleep(uploadPace) + } + if ok, _ := m.upload(svc, id, cfg); ok { + uploaded++ + } + } + return uploaded +} + +// eqslBatchChunk is how many QSOs go into one ImportADIF.cfm request. eQSL's own +// limit is ten times this (eqslBatchMax); the smaller chunk keeps one refused +// record from taking a thousand others down with it, and keeps the form body +// small enough to be unremarkable. +const eqslBatchChunk = 100 + +// flushEQSLBatch uploads the on-close eQSL QSOs through ImportADIF.cfm in +// batches instead of one request per contact. Same reasoning as +// flushClublogBatch — eQSL's import endpoint has always taken a whole file, so +// the one-at-a-time loop was making hundreds of requests it never needed to. +func (m *Manager) flushEQSLBatch(ids []int64, cfg ServiceConfig) int { + uploaded := 0 + var records []string + var kept []int64 + + send := func() { + if len(records) == 0 { + return + } + // nil client: UploadEQSLBatch then builds one with a 30 s timeout rather + // than reusing the 20 s budget of a single realtime QSO. + res, err := UploadEQSLBatch(context.Background(), nil, cfg.Username, cfg.Password, cfg.QTHNickname, records) + if err != nil || !res.OK { + if err == nil { + err = errFromResult(res) + } + m.logf("extsvc: eqsl batch upload (%d QSOs) failed: %v", len(kept), err) + if m.deps.NotifyError != nil { + m.deps.NotifyError(ServiceEQSL, 0, err) + } + } else { + // res.Ignored means eQSL took the file but left records out. Say the + // count out loud: the whole chunk is still marked sent (eQSL never + // says WHICH it dropped, and in practice they are QSOs it already + // had), so the log line is the only trace of the shortfall. + if res.Ignored { + m.logf("extsvc: eqsl batch upload PARTIAL (%d QSOs sent) %s", len(kept), res.Message) + } else { + m.logf("extsvc: eqsl batch upload OK (%d QSOs) %s", len(kept), res.Message) + } + if m.deps.MarkUploaded != nil { + for _, id := range kept { + m.deps.MarkUploaded(ServiceEQSL, id, res.LogID) + } + } + uploaded += len(kept) + } + records = records[:0] + kept = kept[:0] + } + + for _, id := range ids { + if m.deps.ShouldUpload != nil && !m.deps.ShouldUpload(ServiceEQSL, id) { + continue + } + // eQSL keeps the QSO's own station call; the account is identified by the + // credentials and the optional QTH nickname — as in upload(). + rec, ok := m.deps.BuildADIF(id, "") + if !ok { + continue + } + records = append(records, rec) + kept = append(kept, id) + if len(records) >= eqslBatchChunk { + send() + } + } + send() + return uploaded +} + +// clublogBatchChunk is how many QSOs go into one putlogs.php request. Club Log +// dedupes server-side, so chunking is not about correctness — it keeps a single +// malformed record from failing a whole ten-thousand-QSO document, and matches +// what the QSL Manager's bulk upload already uses. +const clublogBatchChunk = 100 + +// flushClublogBatch uploads the on-close Club Log QSOs through the BATCH +// endpoint (putlogs.php) rather than one realtime.php call each. +// +// It used to walk the ids and call UploadClublog per QSO. On-close upload sweeps +// the WHOLE logbook, so importing an ADIF — or simply switching Club Log on over +// an existing log — turned one app close into hundreds of realtime.php posts. +// That endpoint is reserved for an operator logging contacts as they work them, +// and Club Log blocks the IP of anything that batches through it: an OpsLog user +// was flagged by G7VJR for 185 QSOs in four minutes, which is this loop, not a +// pile-up. Batch upload is the mechanism Club Log provides for exactly this. +func (m *Manager) flushClublogBatch(ids []int64, cfg ServiceConfig) int { + uploaded := 0 + var records []string + var kept []int64 + + send := func() { + if len(records) == 0 { + return + } + // nil client on purpose: UploadClublogADIF then builds one with a 120 s + // timeout. m.deps.Client is the 20 s budget of a single realtime QSO, + // which a hundred-QSO document on a slow link would blow through. + res, err := UploadClublogADIF(context.Background(), nil, cfg, strings.Join(records, "\n")) + if err != nil || !res.OK { + if err == nil { + err = errFromResult(res) + } + m.logf("extsvc: clublog batch upload (%d QSOs) failed: %v", len(kept), err) + if m.deps.NotifyError != nil { + m.deps.NotifyError(ServiceClublog, 0, err) + } + } else { + m.logf("extsvc: clublog batch upload OK (%d QSOs) %s", len(kept), res.Message) + if m.deps.MarkUploaded != nil { + for _, id := range kept { + m.deps.MarkUploaded(ServiceClublog, id, res.LogID) + } + } + uploaded += len(kept) + } + records = records[:0] + kept = kept[:0] + } + + for _, id := range ids { + // Skip QSOs not eligible (already sent). The wrong-logbook guard that + // upload() applies per QSO is not repeated here: closeUploadIDs has + // already filtered the sweep down to this logbook's callsign. + if m.deps.ShouldUpload != nil && !m.deps.ShouldUpload(ServiceClublog, id) { + continue + } + // Club Log takes the logbook callsign as its own form field, so the ADIF + // keeps the QSO's own station call (no override) — as in upload(). + rec, ok := m.deps.BuildADIF(id, "") + if !ok { + continue + } + records = append(records, rec) + kept = append(kept, id) + if len(records) >= clublogBatchChunk { + send() + } + } + send() + return uploaded +} + // flushLoTWBatch signs+uploads all queued LoTW QSOs in one TQSL run, then // stamps each as uploaded on success. func (m *Manager) flushLoTWBatch(ids []int64, cfg ServiceConfig) int { diff --git a/telemetry.go b/telemetry.go index 44c2aaa..2b8f73a 100644 --- a/telemetry.go +++ b/telemetry.go @@ -21,7 +21,7 @@ import ( const ( // appVersion is stamped on every heartbeat (and could feed the About box). - appVersion = "0.25.7" + appVersion = "0.25.8" // posthogHost is the PostHog ingestion endpoint. EU cloud by default; change // to https://us.i.posthog.com for a US project.