OpsLog/internal/winkeyer/hostopen.go

package winkeyer

import (
	"errors"
	"fmt"
	"time"

	"go.bug.st/serial"

	"hamlog/internal/applog"
)

// The opening handshake, as K1EL specifies it in the WinKeyer2 Application
// Interface Guide ("WK Init Psuedo Code"). OpsLog used to send Host Open alone
// and carry on whatever came back, which is how an operator ended up with a
// keyer reported as connected, a full set of settings written to it, and not
// one character keyed — the log said "no reply" and then behaved as if there
// had been one.
//
// The steps exist for reasons that are not obvious from the byte values:
//
//	400 ms   a WK1 is still powering up off the DTR line when the port opens;
//	         WK2 and later do not need it, and it costs nothing once.
//	0x13 ×3  null commands. WinKey's parser may be part-way through a command
//	         left over from whoever spoke to it last — another logger, or us
//	         before a crash. A command byte expecting parameters would swallow
//	         Host Open whole. Three nulls flush that state out.
//	echo     ask the keyer to send one known byte back. This is the only step
//	         that answers "is there really a WinKeyer on this port", and it is
//	         the one to fail on: everything after it assumes a listener.
//	open     0x00 0x02, and the keyer returns its firmware version.
const (
	cmdNull     = 0x13
	cmdAdmin    = 0x00
	adminReset  = 0x01
	adminOpen   = 0x02
	adminClose  = 0x03
	adminEcho   = 0x04
	echoProbe   = 0x55 // K1EL's own choice; any byte works, this one is 0b01010101
	bootDelay   = 400 * time.Millisecond
	echoTimeout = 2 * time.Second // K1EL: "if a WK doesn't respond within 2 seconds abort"
	openTimeout = 2 * time.Second

	// resetDelay is the second attempt's wait, and it is not there for a K1EL.
	//
	// Plenty of "WinKeyers" are a K3NG keyer — an Arduino running an emulation
	// of the same protocol. On an Arduino, DTR is wired to the reset pin through
	// a capacitor: raising it when the port opens REBOOTS the board, which then
	// sits in its bootloader before the sketch even starts. K3NG's own options
	// file says as much ("disabling Automatic Software Reset is highly
	// recommended", and an option to "discard errant serial port bytes at
	// startup" for when it is not). 400 ms is nowhere near long enough, so the
	// keyer misses the whole handshake and looks absent.
	//
	// Rather than make every operator wait for the slowest possible device, the
	// first attempt stays quick and only the retry allows for a reboot.
	resetDelay   = 2500 * time.Millisecond
	handshakeTry = 2
)

// errNoKeyer is returned when nothing answers the echo probe.
var errNoKeyer = errors.New("no WinKeyer answered on this port — check the cable, the port, and that no other program holds the keyer")

// hostOpen runs the full documented handshake and returns the firmware version
// byte. It is tried twice, and the two attempts cover the two ways a keyer that
// is plugged in and working can miss being spoken to: a parser left mid-command
// by whoever talked to it last (the first attempt's nulls clear that), and an
// Arduino-based keyer still rebooting from the DTR edge (the second attempt
// waits long enough for it).
// slowBoot skips straight to the long wait, set when this port has already been
// seen to need it. The second return value says whether the long wait is what
// worked, so the caller can remember it and open quickly next time.
func hostOpen(p serial.Port, slowBoot bool) (ver int, needsSlowBoot bool, err error) {
	var lastErr error
	for attempt := 1; attempt <= handshakeTry; attempt++ {
		wait := bootDelay
		if attempt > 1 || slowBoot {
			wait = resetDelay
		}
		// A port already known to need the slow path gets the wake-up on the
		// FIRST attempt too: it needed it last time, and making the operator
		// wait through a failure to earn it again is a connect that takes twice
		// as long for no new information.
		ver, err := hostOpenOnce(p, wait, attempt > 1 || slowBoot)
		if err == nil {
			if attempt > 1 {
				applog.Printf("winkeyer: answered on attempt %d — this keyer needs %s to boot (a K3NG or another Arduino keyer with auto-reset on); remembering that for this port", attempt, wait)
			}
			return ver, wait == resetDelay, nil
		}
		lastErr = err
		if attempt < handshakeTry {
			applog.Printf("winkeyer: handshake attempt %d failed (%v) — retrying after %s in case the keyer is rebooting", attempt, err, resetDelay)
		}
	}
	return 0, false, lastErr
}

func hostOpenOnce(p serial.Port, boot time.Duration, hard bool) (int, error) {
	if hard {
		recoverKeyer(p)
	}
	// The keyer may still be booting off the DTR line we just raised.
	time.Sleep(boot)
	drain(p)

	// The resync nulls and the echo probe go out as ONE write.
	//
	// Copied byte for byte from a Logger32 capture against the K3NG keyer that
	// would not answer OpsLog: "Sent: 13 13 13 00 04 55 / Rcvd: 55". Same keyer,
	// same port, same six bytes — the only difference was that we sent them as
	// two writes with a pause and a buffer purge in between, and Logger32 sends
	// them as one. On a keyer that reboots when the port opens, that pause is a
	// window for it to come up mid-sequence and swallow half of it.
	//
	// There is nothing to wait for between the two halves anyway: a null produces
	// no reply, so the pause was only ever giving the keyer a chance to change
	// its mind.
	probe := []byte{cmdNull, cmdNull, cmdNull, cmdAdmin, adminEcho, echoProbe}
	traceHandshake("TX", probe, 0, false)
	if _, err := p.Write(probe); err != nil {
		return 0, fmt.Errorf("echo test: %w", err)
	}
	b, ok := readByte(p, echoTimeout)
	traceHandshake("RX", nil, b, ok)
	if !ok {
		return 0, errNoKeyer
	}
	if b != echoProbe {
		// Something replied, but not what we asked for. Say what came back —
		// on a wrong port that byte is the only clue to what is on the other end.
		return 0, fmt.Errorf("echo test: expected 0x%02X, got 0x%02X — is this the keyer's port?", echoProbe, b)
	}

	open := []byte{cmdAdmin, adminOpen}
	traceHandshake("TX", open, 0, false)
	if _, err := p.Write(open); err != nil {
		return 0, fmt.Errorf("host open: %w", err)
	}
	ver, ok := readByte(p, openTimeout)
	traceHandshake("RX", nil, ver, ok)
	if !ok {
		// It answered the echo, so there IS a keyer on this port — it simply
		// will not open. A keyer already IN host mode does exactly that: a
		// previous session that ended badly never sent Host Close, and it has
		// been waiting ever since for a host that went away. Close it and ask
		// again.
		applog.Printf("winkeyer: echoed but did not open — closing a host session left over from last time, and asking again")
		if _, err := p.Write([]byte{cmdAdmin, adminClose}); err != nil {
			return 0, fmt.Errorf("host close: %w", err)
		}
		time.Sleep(250 * time.Millisecond)
		drain(p)
		traceHandshake("TX", open, 0, false)
		if _, err := p.Write(open); err != nil {
			return 0, fmt.Errorf("host open: %w", err)
		}
		ver, ok = readByte(p, openTimeout)
		traceHandshake("RX", nil, ver, ok)
		if !ok {
			return 0, errors.New("host open: the keyer echoed but did not return its firmware version")
		}
	}
	return int(ver), nil
}

// recoverKeyer does to the keyer what running K1EL's WKdemo and closing it
// again does — which is the workaround an operator found for a WKUSB that
// OpsLog could not open until they had.
//
// Three things, in an order that survives each of them failing:
//
//   - Host Close, in case the keyer is still in host mode from a session that
//     ended without one: a crash, a cable pulled, a machine switched off.
//   - Admin Reset, which returns it to its power-up state. A parser stuck
//     part-way through a command whose parameters will never arrive cannot be
//     talked out of it any other way.
//   - A DTR pulse. That is what closing another program actually does to the
//     line, and on the boxes that wire DTR to the processor's reset — a WKUSB,
//     and every Arduino-based clone — it is a power-on reset in all but name.
//
// RTS is left alone throughout: on a serial WinKeyer it is the negative rail
// the RS-232 swing comes from, and driving it starves the chip.
func recoverKeyer(p serial.Port) {
	applog.Printf("winkeyer: waking the keyer — host close, reset, then a DTR pulse")
	_, _ = p.Write([]byte{cmdNull, cmdNull, cmdNull, cmdAdmin, adminClose})
	time.Sleep(150 * time.Millisecond)
	_, _ = p.Write([]byte{cmdAdmin, adminReset})
	time.Sleep(150 * time.Millisecond)
	_ = p.SetDTR(false)
	time.Sleep(250 * time.Millisecond)
	_ = p.SetDTR(true)
	drain(p)
}

// traceHandshake puts the opening exchange in the log, ALWAYS — unlike the
// running trace beside it, which is behind the diagnostic option.
//
// A failure that says only "no WinKeyer answered" cannot be told apart from a
// wrong port, a wrong baud rate, a keyer still rebooting, or another program
// holding the line. The bytes can. It is four lines per connect, and only when
// the connect is attempted.
func traceHandshake(dir string, b []byte, got byte, ok bool) {
	switch {
	case dir == "TX":
		applog.Printf("winkeyer: handshake TX % 02X", b)
	case ok:
		applog.Printf("winkeyer: handshake RX %02X", got)
	default:
		applog.Printf("winkeyer: handshake RX — nothing came back")
	}
}

// readByte waits up to d for one byte. The serial read timeout is per-call and
// can return 0 bytes without an error, so this loops until the deadline rather
// than trusting a single Read.
func readByte(p serial.Port, d time.Duration) (byte, bool) {
	_ = p.SetReadTimeout(200 * time.Millisecond)
	deadline := time.Now().Add(d)
	buf := make([]byte, 1)
	for time.Now().Before(deadline) {
		n, err := p.Read(buf)
		if n > 0 {
			return buf[0], true
		}
		if err != nil {
			return 0, false
		}
	}
	return 0, false
}

// drain throws away anything already waiting — a status byte from a previous
// session, or the tail of a reply we are no longer interested in.
func drain(p serial.Port) {
	_ = p.SetReadTimeout(20 * time.Millisecond)
	buf := make([]byte, 64)
	for i := 0; i < 16; i++ {
		n, err := p.Read(buf)
		if n == 0 || err != nil {
			return
		}
	}
}