diff --git a/CHANGELOG.md b/CHANGELOG.md index 1b9defad..57a11834 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -60,10 +60,14 @@ Detailed per-release notes are on the from v1.13.10 on recognises the repeat and keeps one copy; one through v1.13.9 can store the message twice when the ack of its untagged copy is the one lost. A `--trace` message is never sent again: receivers do not - suppress repeated trace frames. Receivers that predate message IDs still - get the message, in the old format (`"tagged": false` in the result); that - costs one extra exchange on the same connection. No dependency change: the - dataexchange release already required carries the IDs. + suppress repeated trace frames. Receivers that predate message IDs + (v1.13.9 and older) still get the message, in the old format + (`"tagged": false` in the result). They store nothing for the message + carrying the ID, so it is sent to them a second time on the same + connection, without the ID: the whole payload, up to 64 MiB, crosses the + network twice, and twice more when its ack is lost and it is sent again. + No dependency change: the dataexchange release already required carries + the IDs. - **The daemon caps its own log file.** launchd never rotates the daemon's `StandardOutPath`/`StandardErrorPath` (`~/.pilot/daemon.log`), which grew without bound — 22 MB on one laptop. When stderr is a regular file the @@ -318,6 +322,25 @@ Detailed per-release notes are on the Hosts with many cores can cut scheduler overhead further by setting `GOMAXPROCS` (for example 4) in the daemon's environment. +- **`pilotctl dgram` exits with a code that says whether to retry.** Every + datagram the daemon refused was `connection_failed`, which the error-code + list calls retryable, though a port the network's policy forbids or a + datagram too large to send fails the same way every time. The `code` in + the error (and in `--json`) now follows the reason, so scripts that + matched `connection_failed` for these see a different code: + - a port the network's policy does not allow: `permission_denied` (now in + the `pilotctl context` error-code list); + - a payload too large for a packet, the tunnel socket or the IPC frame, + or a broadcast address: `invalid_argument`; + - a node the registry does not know: `not_found`; + - a datagram that waited too long for its turn and was not sent: + `timeout`, as one whose answer did not come in time already was; + - anything else (no route or tunnel yet, a key exchange in progress, the + registry unreachable, ephemeral ports exhausted): `connection_failed`, + as before. + + A `--data` over 65535 bytes is now refused before the daemon is + contacted. - **The tunnel socket asks the kernel for 4 MB buffers** in each direction instead of the default (about 200 KB on Linux). Every tunnel shares the one socket, and several streams sending at once overflowed it. The kernel caps @@ -393,6 +416,34 @@ Detailed per-release notes are on the reconnect and full re-registration a recovery has just done. A recovery whose re-registration failed, or that restored the node's visibility, hostname or trust pairs only in part, does not count as done. +- **`pilotctl send-message --count N --reuse-conn` carries on after a lost + ack.** A lost ack means the shared connection is gone, but the messages + after it were still written into it. The driver only notices a connection + it closed itself, so those writes appeared to succeed and were dropped. Each + later message then lost its ack too and was sent again on a new connection: + every message showed `"retried": true`, and with `--no-resend` every + message after the lost one failed. The messages after it now go on the + retry's connection, or on a new one when there was no retry. `reused` is + true only when the connection had carried an earlier message. A later + message whose new connection cannot be dialled is reported as failed, and + the run goes on. +- **A failed `pilotctl send-message` says which message failed.** When a + single message could not be sent, was not acknowledged or was refused by + the receiver, the `--json` error did not include its `message_id`, so the + caller could not look for it in the receiver's inbox or for a reply naming + it. The error now carries the message's result in `results`, as a + `--count` run's error already did. A refused message's error also gets a + `hint`. +- **`pilotctl bench` fails when the echo does not all come back.** A run + whose echo stopped short printed `"status":"ok"` and exited 0: with the + echo cut off after 2 KiB, `bench 0.01 --timeout 300ms` reported + 4096 of 10485 bytes received as a success. Such a run now **exits 1**, + with code `timeout` when `--timeout` ended the wait for the echo, or + `connection_failed` when the echo stream ended early, and the error's + `results` carry the partial figures. A complete run adds + `"complete": true` to its result. `total_mbps` is now computed from the + bytes that came back rather than the bytes sent, and the received count is + no longer read while the reader may still be writing it (a data race). - **A bulk transfer no longer hangs when the receiver's application falls behind.** When a receiver's application stops reading for a second, the receiver parks the next in-order segment in its reorder buffer and keeps diff --git a/cmd/pilotctl/main.go b/cmd/pilotctl/main.go index 9ea6b735..bbc60188 100644 --- a/cmd/pilotctl/main.go +++ b/cmd/pilotctl/main.go @@ -21,6 +21,7 @@ import ( "sort" "strconv" "strings" + "sync/atomic" "syscall" "time" @@ -934,6 +935,11 @@ sender and arrival time, as before. From a peer known to echo IDs (one of its earlier messages in the inbox carries a reply_to) such a reply is held back until 0.75s after it arrived, in case the reply naming the ID follows. +A receiver from v1.13.9 or older does not know message IDs and stores nothing +for the message carrying one. It is sent the whole message a second time, +without the ID ("tagged": false), so the payload (up to 64 MiB) crosses the +network twice, and twice more if an ack is lost and the message is re-sent. + Examples: pilotctl send-message list-agents --data '/data {"search":"weather","limit":5}' pilotctl send-message my-peer --data "hello" --wait @@ -959,6 +965,10 @@ Examples: Measure throughput to a remote node via the echo port. +The run fails unless everything sent is echoed back: with code timeout when +--timeout ends the wait for the echo, connection_failed when the echo stream +ends early. The error's "results" carry the partial figures. + Flags: --timeout overall deadline (default: 120s) @@ -1401,6 +1411,13 @@ have no ACK, no retry and no ordering guarantee. The local daemon does say whether it sent the datagram: if it could not (no route to the node, port policy, payload too large) the command fails with its reason. "confirmed": false means the daemon is too old to say, and the datagram was sent anyway. +The daemon refuses a payload over 65535 bytes, and less fits in practice: +the datagram and its headers must fit one UDP packet, about 65400 bytes on a +direct path and less relayed. Use send-message for anything large. + +The error code says whether sending again can help: permission_denied (the +network's port policy), invalid_argument (too large), not_found (no such +node), timeout, or connection_failed (no route or tunnel yet; may retry). Use for: real-time telemetry, heartbeats, anything where freshness > reliability. `, @@ -2687,6 +2704,7 @@ func contextCatalog() map[string]interface{} { "error_codes": map[string]interface{}{ "invalid_argument": "Bad input or usage error (do not retry)", "not_found": "Resource not found (hostname/name resolve failure)", + "permission_denied": "Refused by policy or verification (do not retry unchanged)", "already_exists": "Duplicate operation (daemon/gateway already running)", "not_running": "Service not available (daemon/gateway not running)", "connection_failed": "Network or dial failure (may retry)", @@ -4481,15 +4499,6 @@ func cmdDgram(args []string) { if len(pos) < 2 { fatalCode("invalid_argument", "usage: pilotctl dgram --data ") } - - d := connectDriver() - defer d.Close() - - target, err := parseAddrOrHostname(d, pos[0]) - if err != nil { - fatalCode("not_found", "%v", err) - } - maybeAutoHandshake(d, target, flagBool(flags, "no-auto-handshake")) p, err := strconv.ParseUint(pos[1], 10, 16) if err != nil { fatalCode("invalid_argument", "invalid port %q: %v", pos[1], err) @@ -4500,17 +4509,36 @@ func cmdDgram(args []string) { if data == "" { fatalCode("invalid_argument", "--data is required") } + // A packet's payload length is 16 bits: the daemon refuses anything + // larger, so say so before contacting it. Headers take some of the UDP + // packet, so slightly smaller payloads can still fail to send; the + // daemon reports those. + if len(data) > maxDatagramBytes { + fatalCode("invalid_argument", "datagram is %d bytes; the daemon refuses more than %d, and less fits after headers (use send-message for larger payloads)", len(data), maxDatagramBytes) + } + + d := connectDriver() + defer d.Close() + + target, err := parseAddrOrHostname(d, pos[0]) + if err != nil { + fatalCode("not_found", "%v", err) + } + maybeAutoHandshake(d, target, flagBool(flags, "no-auto-handshake")) // The daemon says whether it sent the datagram. The fire-and-forget // send reported success even when the daemon could not send it (no // route to the node, port policy, ephemeral ports exhausted). confirmed, err := d.SendToConfirmed(target, port, []byte(data)) if err != nil { - if errors.Is(err, driver.ErrConfirmTimeout) { + switch { + case errors.Is(err, driver.ErrConfirmTimeout): fatalHint("timeout", "the datagram may or may not have been sent; datagrams are unreliable, so send it again if it matters", "%v", err) + case errors.Is(err, driver.ErrConfirmQueueTimeout): + fatalHint("timeout", "the datagram was not sent; send it again", "%v", err) } // The driver's error already names the step ("daemon: sendto: ..."). - fatalCode("connection_failed", "%v", err) + fatalCode(dgramErrorCode(err), "%v", err) } if jsonOutput { @@ -4529,6 +4557,42 @@ func cmdDgram(args []string) { } } +// maxDatagramBytes is the largest payload the daemon accepts for a +// datagram: a packet's payload length field is 16 bits. What fits one UDP +// packet with the headers is somewhat less. +const maxDatagramBytes = 0xFFFF + +// dgramErrorCode is the exit code for a datagram the daemon could not send, +// or that never reached it. The daemon's reasons arrive as "daemon: sendto: +// ". They used to be connection_failed, which the error-code list +// calls retryable, whatever the reason: a port the network's policy forbids +// or a datagram too large to send fails the same way every time. +func dgramErrorCode(err error) string { + if errors.Is(err, driver.ErrConfirmTimeout) || errors.Is(err, driver.ErrConfirmQueueTimeout) { + return "timeout" + } + s := err.Error() + switch { + case strings.Contains(s, "not allowed by network"): + // "port %d not allowed by network %d policy" + return "permission_denied" + case strings.Contains(s, "payload too large"), + strings.Contains(s, "message too long"), + strings.Contains(s, "ipc frame too large"), + strings.Contains(s, "broadcast address requires admin token"): + // Too large for a packet, for the tunnel socket or for the IPC + // frame, or a broadcast address (refused by the driver or the + // daemon). + return "invalid_argument" + case strings.Contains(s, "resolve node") && strings.Contains(s, "not found"): + // The registry does not know the node. + return "not_found" + } + // No route yet, no tunnel, a key exchange in progress, the registry + // unreachable, ports exhausted: sending again may work. + return "connection_failed" +} + // cmdSendFile transfers a file via the dataexchange overlay stream. // // Until the chunked streaming protocol lands (see @@ -5043,22 +5107,37 @@ func cmdSendMessage(args []string) { // redial dials like dialOnce but returns the error: when sendOne's // retry after a lost ack cannot connect, the first attempt stands. redial := func() (*dataexchange.Client, error) { return dataexchange.Dial(d, target) } + // dialFailed is the result of a message of a multi-send whose dial + // failed after earlier messages went out. + dialFailed := func(seq int, err error) map[string]interface{} { + return map[string]interface{}{"seq": seq, "error": fmt.Sprintf("cannot connect to %s (data exchange port %d): %v", target, protocol.PortDataExchange, err)} + } // Set below when --wait is given. Declared here so sendOne can register // each request's message ID with it before the request leaves. var watch *inboxWatch - // sendOne sends one message on cl and returns timing/ack metadata. - // reused=true is recorded when the connection was dialled on a prior call. - // redial opens a new connection to the same receiver, for the one retry - // after a lost ack (below). + // sendOne sends one message on cl and returns timing/ack metadata, and + // the connection the next message can go on. reused=true says cl carried + // an earlier message. redial opens a new connection to the same + // receiver, for the one retry after a lost ack (below). + // + // sendOne takes cl over. It returns cl, or the retry's connection when + // the ack on cl was lost, and closes the connections it does not return. + // It returns nil when neither can carry another message: the next one + // needs a new connection. A failed ack read means the connection is + // gone. No read deadline is set, so the read failed because the + // connection ended, and later writes to it would still succeed (the + // driver only notices a local close) and be dropped. // // Every send carries a new message ID, so the receiver can tell a // re-delivery from a new message and a reply can name the request it // answers (reply_to). Client.Send delivers the message without the ID to - // a receiver too old to know it: such a receiver stores nothing for the - // tagged frame, says so, and gets the plain frame on the same connection. - sendOne := func(cl *dataexchange.Client, seq int, reused bool, redial func() (*dataexchange.Client, error)) map[string]interface{} { + // a receiver too old to know it (v1.13.9 and older): such a receiver + // stores nothing for the tagged frame, says so, and gets the plain frame + // on the same connection. That is the whole payload (up to 64 MiB) sent + // a second time, and a retry after a lost ack (below) sends both again. + sendOne := func(cl *dataexchange.Client, seq int, reused bool, redial func() (*dataexchange.Client, error)) (map[string]interface{}, *dataexchange.Client) { messageID := dataexchange.NewMessageID() if watch != nil { watch.addID(messageID) @@ -5066,6 +5145,13 @@ func cmdSendMessage(args []string) { sentAtNs := time.Now().UnixNano() frame := messageFrame(innerType, []byte(data), messageID, replyTo, traceTime, sentAtNs) res, sendErr := cl.Send(frame) + next := cl + if res == nil { + // Not answered: the write failed, or the ack read did. Either way + // cl cannot carry another message. + _ = cl.Close() + next = nil + } retried := false if res == nil && isAckReadError(sendErr) && !noResend && !traceTime { // The frame was written but no ack came back, so whether it was @@ -5075,7 +5161,8 @@ func cmdSendMessage(args []string) { // Send the same frame once more on a new connection: a receiver // from v1.13.10 on recognises the repeat by its ID and keeps one // copy, and an older one answers the tagged frame again and gets - // the untagged copy. The one case that stores the message twice + // the untagged copy (the payload crosses the network twice more + // for it). The one case that stores the message twice // is a receiver through v1.13.9 that stored the untagged copy // and lost its ack; --no-resend opts out of the retry. A --trace // message is never sent again: receivers do not suppress @@ -5090,13 +5177,20 @@ func cmdSendMessage(args []string) { res2, err2 := c2.Send(frame) switch { case res2 != nil, isAckReadError(err2): - res, sendErr = res2, err2 + // The retry's outcome is the message's, on a connection + // that carried nothing before. + res, sendErr, reused = res2, err2, false default: // The retry was not written: the first attempt, written // but unacknowledged, is what happened to the message. sendErr = fmt.Errorf("%w; sending again failed: %v", sendErr, err2) } - _ = c2.Close() + if res2 != nil { + // Answered, so still open: the next message goes on it. + next = c2 + } else { + _ = c2.Close() + } } } ackRecvAtNs := time.Now().UnixNano() @@ -5112,7 +5206,7 @@ func cmdSendMessage(args []string) { slog.Debug("send-message ACK read failed", "err", sendErr) ackErr = sendErr default: - return map[string]interface{}{"seq": seq, "error": sendErr.Error(), "message_id": messageID} + return map[string]interface{}{"seq": seq, "error": sendErr.Error(), "message_id": messageID}, next } if res != nil && res.Tagged && watch != nil { watch.markTagged() @@ -5167,7 +5261,7 @@ func cmdSendMessage(args []string) { } } } - return r + return r, next } tracef("dial+send") @@ -5211,8 +5305,10 @@ func cmdSendMessage(args []string) { "cannot connect to %s (data exchange port %d)", target, protocol.PortDataExchange) } tracef("dataexchange.Dial") - defer cl.Close() - r := sendOne(cl, 0, false, redial) + r, cl := sendOne(cl, 0, false, redial) + if cl != nil { + defer cl.Close() + } ackAt := time.Now() // Every receiver answers a stored message with an ACK frame. No ACK // means the message was not stored, or was never sent — the daemon @@ -5220,7 +5316,12 @@ func cmdSendMessage(args []string) { // "ok" here was reporting messages that never arrived. A send that // failed outright was reported as "ok" with an error field; it is a // failure too. + // + // The error carries the message's result, as a --count run's does: + // its message_id is how the caller finds the message later, in the + // receiver's inbox or in a reply that names it. if e, failed := r["error"].(string); failed { + fatalResults = []map[string]interface{}{r} fatalHint("connection_failed", "the message was not sent; check `pilotctl peers` and the daemon log, then send again", "sending to %s failed: %s", target, e) @@ -5230,6 +5331,7 @@ func cmdSendMessage(args []string) { if e, ok := r["ack_error"].(string); ok { why = ": " + e } + fatalResults = []map[string]interface{}{r} fatalHint("connection_failed", "the receiver did not confirm it stored the message; check `pilotctl peers` and the daemon log, then send again", "%s did not acknowledge the message (%d bytes)%s", target, len(data), why) @@ -5238,7 +5340,9 @@ func cmdSendMessage(args []string) { // message (disk full, inbox unwritable). That is a failed send, not // a delivered one — same rule send-file applies. if rej := refusal(r); rej != "" { - fatalCode("internal", "receiver rejected message: %s", rej) + fatalResults = []map[string]interface{}{r} + fatalHint("internal", "the receiver did not store the message; send it again once the receiver can store it", + "receiver rejected message: %s", rej) } result := map[string]interface{}{ "target": target.String(), @@ -5285,8 +5389,10 @@ func cmdSendMessage(args []string) { if err != nil { return time.Time{}, err } - defer c.Close() - rr := sendOne(c, 1, false, func() (*dataexchange.Client, error) { return dataexchange.Dial(rd, target) }) + rr, c := sendOne(c, 1, false, func() (*dataexchange.Client, error) { return dataexchange.Dial(rd, target) }) + if c != nil { + _ = c.Close() + } if e, failed := rr["error"].(string); failed { return time.Time{}, errors.New(e) } @@ -5332,16 +5438,33 @@ func cmdSendMessage(args []string) { } else if reuseConn { // --reuse-conn: one dial shared across all N sends. Seq 0 pays dial // cost; seqs 1+ skip it. Savings ≈ one relay RTT (~70ms) per msg. + // A connection whose ack was lost is gone: the messages after it go + // on the retry's connection, or on a new one. cl := dialOnce() tracef("dataexchange.Dial (shared)") - defer cl.Close() + defer func() { + if cl != nil { + _ = cl.Close() + } + }() + carried := false // cl carried an earlier message var results []map[string]interface{} for i := 0; i < sendCount; i++ { - result := sendOne(cl, i, i > 0, redial) - results = append(results, result) - if i < sendCount-1 { + if i > 0 { time.Sleep(50 * time.Millisecond) } + if cl == nil { + c, err := redial() + if err != nil { + results = append(results, dialFailed(i, err)) + continue + } + cl, carried = c, false + } + var result map[string]interface{} + result, cl = sendOne(cl, i, carried, redial) + results = append(results, result) + carried = cl != nil } failIfUndelivered(target.String(), results) outputOK(map[string]interface{}{ @@ -5356,13 +5479,27 @@ func cmdSendMessage(args []string) { // baseline — measures true per-message cost including dial overhead. var results []map[string]interface{} for i := 0; i < sendCount; i++ { - cl := dialOnce() - result := sendOne(cl, i, false, redial) - results = append(results, result) - cl.Close() - if i < sendCount-1 { + if i > 0 { time.Sleep(50 * time.Millisecond) } + // The first dial fails the command, as for one message. A + // later one is recorded against its message, so the results + // still list the messages already delivered. + var c *dataexchange.Client + if i == 0 { + c = dialOnce() + } else { + var err error + if c, err = redial(); err != nil { + results = append(results, dialFailed(i, err)) + continue + } + } + result, cl := sendOne(c, i, false, redial) + results = append(results, result) + if cl != nil { + _ = cl.Close() + } } failIfUndelivered(target.String(), results) outputOK(map[string]interface{}{ @@ -6869,17 +7006,19 @@ func cmdBench(args []string) { } defer conn.Close() - var recvTotal int + // The reader may still be running when the wait below gives up, so the + // count it keeps is atomic. + var recvTotal atomic.Int64 recvDone := make(chan struct{}) go func() { defer close(recvDone) buf := make([]byte, 65535) - for recvTotal < totalSize { + for recvTotal.Load() < int64(totalSize) { n, err := conn.Read(buf) if err != nil { return } - recvTotal += n + recvTotal.Add(int64(n)) } }() @@ -6906,34 +7045,53 @@ func cmdBench(args []string) { // Waiting for the full echo to come back is the silent half of the // benchmark — on a slow path it can run to --timeout with no output. stopProgress := startWaitProgress(fmt.Sprintf("benchmarking %s", target)) + timedOut := false select { case <-recvDone: - stopProgress() case <-time.After(timeout): - stopProgress() - if !jsonOutput { - fmt.Printf("warning: receive timed out (got %s of %s)\n", - formatBytes(uint64(recvTotal)), formatBytes(uint64(totalSize))) - } + timedOut = true } + stopProgress() totalDuration := time.Since(start) + received := int(recvTotal.Load()) sendThroughput := float64(totalSize) / sendDuration.Seconds() / 1024 / 1024 - totalThroughput := float64(totalSize) / totalDuration.Seconds() / 1024 / 1024 - - if jsonOutput { - output(map[string]interface{}{ - "target": target.String(), - "sent_bytes": sent, - "recv_bytes": recvTotal, - "send_duration_ms": float64(sendDuration.Milliseconds()), - "total_duration_ms": float64(totalDuration.Milliseconds()), - "send_mbps": sendThroughput, - "total_mbps": totalThroughput, - }) - } else { + // The round trip carried what came back, which is less than was sent + // when the echo stopped short. + totalThroughput := float64(received) / totalDuration.Seconds() / 1024 / 1024 + complete := received >= totalSize + + stats := map[string]interface{}{ + "target": target.String(), + "sent_bytes": sent, + "recv_bytes": received, + "send_duration_ms": float64(sendDuration.Milliseconds()), + "total_duration_ms": float64(totalDuration.Milliseconds()), + "send_mbps": sendThroughput, + "total_mbps": totalThroughput, + "complete": complete, + } + if !jsonOutput { fmt.Printf(" Sent: %s in %v (%.1f MB/s)\n", formatBytes(uint64(sent)), sendDuration.Round(time.Millisecond), sendThroughput) - fmt.Printf(" Echoed: %s in %v (%.1f MB/s round-trip)\n", formatBytes(uint64(recvTotal)), totalDuration.Round(time.Millisecond), totalThroughput) + fmt.Printf(" Echoed: %s in %v (%.1f MB/s round-trip)\n", formatBytes(uint64(received)), totalDuration.Round(time.Millisecond), totalThroughput) + } + // A partial echo is a failed benchmark, not a slow one: it used to be + // reported as "ok". The error carries the figures, as a failed + // send-message --count carries each message's result. + if !complete { + fatalResults = []map[string]interface{}{stats} + got := fmt.Sprintf("%s of %s", formatBytes(uint64(received)), formatBytes(uint64(totalSize))) + if timedOut { + fatalHint("timeout", + fmt.Sprintf("the path is slow or losing data: check `pilotctl ping %s`, or try a smaller size or a longer --timeout", target), + "%s echoed %s within --timeout %s", target, got, timeout) + } + fatalHint("connection_failed", + fmt.Sprintf("the echo stream ended early; check `pilotctl ping %s` and the daemon log", target), + "the echo stream from %s ended after %s", target, got) + } + if jsonOutput { + output(stats) } } diff --git a/cmd/pilotctl/zz_reply_match_test.go b/cmd/pilotctl/zz_reply_match_test.go index 8f4f2ee6..f08664d6 100644 --- a/cmd/pilotctl/zz_reply_match_test.go +++ b/cmd/pilotctl/zz_reply_match_test.go @@ -181,15 +181,18 @@ const dxCutAck = "\x00cut" // dxReceiver turns the stream daemon's echo into a data-exchange receiver: // answer is called with each complete wire frame (its type and payload) the // client wrote and returns the acknowledgement text (or dxDropConnection). +// Like a real daemon, it discards what is written to a connection it has +// closed: the client's driver does not notice, and its writes "succeed". type dxReceiver struct { mu sync.Mutex buf map[uint32][]byte + closed map[uint32]bool types []uint32 frames []*dataexchange.Frame // decoded with the current library } func newDXReceiver(sd *streamDaemon, answer func(ftype uint32, payload []byte, decoded *dataexchange.Frame) string) *dxReceiver { - r := &dxReceiver{buf: map[uint32][]byte{}} + r := &dxReceiver{buf: map[uint32][]byte{}, closed: map[uint32]bool{}} sd.on(tdCmdSend, func(frame []byte) [][]byte { sd.sendCount.Add(1) if len(frame) < 5 { @@ -198,6 +201,9 @@ func newDXReceiver(sd *streamDaemon, answer func(ftype uint32, payload []byte, d connID := binary.BigEndian.Uint32(frame[1:5]) r.mu.Lock() defer r.mu.Unlock() + if r.closed[connID] { + return nil + } r.buf[connID] = append(r.buf[connID], frame[5:]...) var out [][]byte for { @@ -227,6 +233,8 @@ func newDXReceiver(sd *streamDaemon, answer func(ftype uint32, payload []byte, d closed[0] = tdCmdCloseOK binary.BigEndian.PutUint32(closed[1:5], connID) out = append(out, closed) + r.closed[connID] = true + delete(r.buf, connID) break } var ack bytes.Buffer @@ -1071,6 +1079,269 @@ func TestSendMessageSendsAgainWhenTheAckIsLost(t *testing.T) { }) } +// ── --reuse-conn after a lost ack ───────────────────────────────────────── + +// dials is how many connections the client has dialled. +func (sd *streamDaemon) dials() int { + sd.streamMu.Lock() + defer sd.streamMu.Unlock() + return len(sd.dialed) +} + +// errorResults decodes the "results" in the --json error envelope a failed +// command printed to stderr. +func errorResults(t *testing.T, stderr string) []map[string]interface{} { + t.Helper() + var env struct { + Results []map[string]interface{} `json:"results"` + } + i := strings.Index(stderr, "{") + if i < 0 { + t.Fatalf("no error envelope in stderr:\n%s", stderr) + } + if err := json.Unmarshal([]byte(stderr[i:]), &env); err != nil { + t.Fatalf("error envelope: %v\n%s", err, stderr) + } + return env.Results +} + +// The first message's ack is lost, so the shared connection is gone: no read +// deadline is set, so the ack read failed because the connection ended, and +// writes to it would still "succeed" (the driver only notices a local close) +// and be dropped. The messages after it go on the retry's connection, which +// is still open: two dials in all and one retry, and only the later messages +// are reported as reused. Each of them used to be written into the dead +// connection, lose its ack and be sent again on a new one. +func TestSendMessageReuseConnContinuesOnTheRetrysConnection(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + calls := 0 + rcv := newDXReceiver(sd, func(uint32, []byte, *dataexchange.Frame) string { + if calls++; calls == 1 { + return dxDropConnection + } + return "ACK TEXT 5 bytes" + }) + + data := sendMessageJSON(t, "0:0000.0000.002A", "--data", "hello", "--count", "3", "--reuse-conn") + if n := sd.dials(); n != 2 { + t.Errorf("%d dials, want 2: the shared connection and the retry's", n) + } + if types, _ := rcv.seen(); len(types) != 4 { + t.Errorf("receiver got %d frames, want 4: the lost one, its retry and two more", len(types)) + } + results, _ := data["results"].([]interface{}) + if len(results) != 3 { + t.Fatalf("results = %v, want 3", data["results"]) + } + for i, want := range []struct{ retried, reused bool }{{true, false}, {false, true}, {false, true}} { + r := results[i].(map[string]interface{}) + if retried, _ := r["retried"].(bool); retried != want.retried || r["reused"] != want.reused || r["ack"] != "ACK TEXT 5 bytes" { + t.Errorf("message %d = %v, want retried=%v reused=%v", i, r, want.retried, want.reused) + } + } +} + +// With --no-resend the message whose ack was lost is not sent again, and its +// connection is gone: the next message goes on a new one. One message of +// three is undelivered, where all three used to be. +func TestSendMessageReuseConnRedialsAfterALostAckWithoutResend(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + fatalResults = nil + t.Cleanup(func() { fatalResults = nil }) + calls := 0 + newDXReceiver(sd, func(uint32, []byte, *dataexchange.Frame) string { + if calls++; calls == 1 { + return dxDropConnection + } + return "ACK TEXT 5 bytes" + }) + + var stderr string + var f *trappedFatal + withJSON(func() { + _, stderr, f = runTrapped(t, func() { + cmdSendMessage([]string{"0:0000.0000.002A", "--data", "hello", "--count", "3", "--reuse-conn", "--no-resend"}) + }) + }) + if f == nil || f.Code != "connection_failed" || !strings.HasPrefix(f.Message, "1 of 3 messages") { + t.Fatalf("send = %+v, want connection_failed for 1 of 3 messages", f) + } + if n := sd.dials(); n != 2 { + t.Errorf("%d dials, want 2: the shared connection and the one after it was lost", n) + } + results := errorResults(t, stderr) + if len(results) != 3 { + t.Fatalf("results = %v, want 3", results) + } + if _, acked := results[0]["ack"]; acked || results[0]["ack_error"] == nil || results[0]["retried"] != nil { + t.Errorf("message 0 = %v, want unacknowledged and not sent again", results[0]) + } + for i, reused := range []bool{false, true} { + if r := results[i+1]; r["ack"] != "ACK TEXT 5 bytes" || r["reused"] != reused { + t.Errorf("message %d = %v, want acknowledged with reused=%v", i+1, r, reused) + } + } +} + +// The new connection for the message after a lost one cannot be dialled: +// that message fails with the reason, and the one after it dials again. +func TestSendMessageReuseConnReportsAFailedRedialAndGoesOn(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + fatalResults = nil + t.Cleanup(func() { fatalResults = nil }) + sd.mu.Lock() + accept := sd.handlers[tdCmdDial] + sd.mu.Unlock() + var attempts atomic.Int32 + sd.on(tdCmdDial, func(frame []byte) [][]byte { + if attempts.Add(1) == 2 { + return [][]byte{append([]byte{tdCmdError, 0, 1}, "dial timeout"...)} + } + return accept(frame) + }) + calls := 0 + newDXReceiver(sd, func(uint32, []byte, *dataexchange.Frame) string { + if calls++; calls == 1 { + return dxDropConnection + } + return "ACK TEXT 5 bytes" + }) + + var stderr string + var f *trappedFatal + withJSON(func() { + _, stderr, f = runTrapped(t, func() { + cmdSendMessage([]string{"0:0000.0000.002A", "--data", "hello", "--count", "3", "--reuse-conn", "--no-resend"}) + }) + }) + if f == nil || !strings.HasPrefix(f.Message, "2 of 3 messages") { + t.Fatalf("send = %+v, want 2 of 3 messages undelivered", f) + } + results := errorResults(t, stderr) + if len(results) != 3 { + t.Fatalf("results = %v, want 3", results) + } + if e, _ := results[1]["error"].(string); !strings.Contains(e, "cannot connect") || !strings.Contains(e, "dial timeout") { + t.Errorf("message 1 = %v, want the dial failure", results[1]) + } + if r := results[2]; r["ack"] != "ACK TEXT 5 bytes" || r["reused"] != false { + t.Errorf("message 2 = %v, want acknowledged on a new connection", r) + } +} + +// Without --reuse-conn every message dials its own connection. One whose +// dial fails is recorded against that message, as with --reuse-conn: the run +// used to exit at once with no results, losing the message IDs of the ones +// already delivered, and a caller sending them all again duplicated those. +func TestSendMessageCountReportsAFailedDialAndGoesOn(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + fatalResults = nil + t.Cleanup(func() { fatalResults = nil }) + sd.mu.Lock() + accept := sd.handlers[tdCmdDial] + sd.mu.Unlock() + var attempts atomic.Int32 + sd.on(tdCmdDial, func(frame []byte) [][]byte { + if attempts.Add(1) == 2 { + return [][]byte{append([]byte{tdCmdError, 0, 1}, "dial timeout"...)} + } + return accept(frame) + }) + newDXReceiver(sd, func(uint32, []byte, *dataexchange.Frame) string { return "ACK TEXT 5 bytes" }) + + var stderr string + var f *trappedFatal + withJSON(func() { + _, stderr, f = runTrapped(t, func() { + cmdSendMessage([]string{"0:0000.0000.002A", "--data", "hello", "--count", "3", "--no-resend"}) + }) + }) + if f == nil || f.Code != "connection_failed" || !strings.HasPrefix(f.Message, "1 of 3 messages") { + t.Fatalf("send = %+v, want connection_failed for 1 of 3 messages", f) + } + results := errorResults(t, stderr) + if len(results) != 3 { + t.Fatalf("results = %v, want 3", results) + } + for _, i := range []int{0, 2} { + if r := results[i]; r["ack"] != "ACK TEXT 5 bytes" || r["message_id"] == nil { + t.Errorf("message %d = %v, want acknowledged with its message_id", i, r) + } + } + if e, _ := results[1]["error"].(string); !strings.Contains(e, "cannot connect") || !strings.Contains(e, "dial timeout") { + t.Errorf("message 1 = %v, want the dial failure", results[1]) + } +} + +// A single message that fails says which message it was: the error envelope +// carries its result, message_id included, as a --count run's does, so the +// caller can look for it in the receiver's inbox or for a reply naming it. +func TestSendMessageFailureReportsTheMessageID(t *testing.T) { + for name, tc := range map[string]struct { + args []string + answer func(calls int) string + check func(r map[string]interface{}) bool + }{ + "not acknowledged": { + args: []string{"--no-resend"}, + answer: func(int) string { return dxDropConnection }, + check: func(r map[string]interface{}) bool { return r["ack_error"] != nil }, + }, + "retry not acknowledged": { + answer: func(calls int) string { + if calls == 1 { + return dxDropConnection + } + return dxCutAck + }, + check: func(r map[string]interface{}) bool { return r["retried"] == true && r["ack_error"] != nil }, + }, + "refused by the receiver": { + answer: func(int) string { return "ERR TEXT save failed: no space left on device" }, + check: func(r map[string]interface{}) bool { + return r["ack"] == "ERR TEXT save failed: no space left on device" + }, + }, + } { + t.Run(name, func(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + // fatalResults is a package global; one left by another test + // would pass for this one's. + fatalResults = nil + t.Cleanup(func() { fatalResults = nil }) + calls := 0 + newDXReceiver(sd, func(uint32, []byte, *dataexchange.Frame) string { + calls++ + return tc.answer(calls) + }) + + var stderr string + var f *trappedFatal + withJSON(func() { + _, stderr, f = runTrapped(t, func() { + cmdSendMessage(append([]string{"0:0000.0000.002A", "--data", "hello"}, tc.args...)) + }) + }) + if f == nil { + t.Fatal("send succeeded") + } + results := errorResults(t, stderr) + if len(results) != 1 { + t.Fatalf("error envelope results = %v, want the message's result\n%s", results, stderr) + } + r := results[0] + if id, _ := r["message_id"].(string); !dataexchange.ValidMessageID(id) || !tc.check(r) { + t.Errorf("result = %v", r) + } + }) + } +} + // A message whose first ack was lost and whose retry was acknowledged was // delivered: a --count run with it succeeds. func TestUndeliveredCountsARetriedAndAcknowledgedMessageAsDelivered(t *testing.T) { diff --git a/cmd/pilotctl/zz_stream_daemon_test.go b/cmd/pilotctl/zz_stream_daemon_test.go index 57a00730..0b277d07 100644 --- a/cmd/pilotctl/zz_stream_daemon_test.go +++ b/cmd/pilotctl/zz_stream_daemon_test.go @@ -5,6 +5,7 @@ package main import ( "encoding/binary" "encoding/json" + "errors" "fmt" "os" "path/filepath" @@ -14,6 +15,7 @@ import ( "testing" "time" + "github.com/pilot-protocol/common/driver" "github.com/pilot-protocol/common/ipcutil" "github.com/pilot-protocol/common/protocol" ) @@ -418,8 +420,97 @@ func TestCmdDgramReportsTheDaemonsRefusal(t *testing.T) { if failure == nil { t.Fatal("dgram succeeded although the daemon refused the send") } - if failure.Code != "connection_failed" || !strings.Contains(failure.Message, "not allowed by network 0 policy") || strings.Count(failure.Message, "sendto:") != 1 { - t.Errorf("failure = %+v, want connection_failed naming the daemon's reason", failure) + if failure.Code != "permission_denied" || !strings.Contains(failure.Message, "not allowed by network 0 policy") || strings.Count(failure.Message, "sendto:") != 1 { + t.Errorf("failure = %+v, want permission_denied naming the daemon's reason", failure) + } +} + +// Each kind of refusal gets the code that says whether sending again can +// help. Every one of them used to be connection_failed, which the error-code +// list calls retryable. +func TestDgramErrorCode(t *testing.T) { + for _, tc := range []struct { + err error + want string + }{ + {errors.New("daemon: sendto: port 9999 not allowed by network 0 policy"), "permission_denied"}, + {errors.New("daemon: sendto: marshal: payload too large: 70000 bytes (max 65535)"), "invalid_argument"}, + {errors.New("daemon: sendto: write udp [::]:4000->192.0.2.1:4000: sendto: message too long"), "invalid_argument"}, + {errors.New("ipc frame too large: 1048600 bytes"), "invalid_argument"}, + {errors.New("broadcast address requires admin token: use Driver.Broadcast"), "invalid_argument"}, + {errors.New("daemon: sendto: broadcast address requires admin token: use BroadcastDatagram"), "invalid_argument"}, + {errors.New("daemon: sendto: resolve node 42: node 42: not found"), "not_found"}, + {errors.New("daemon: sendto: resolve node 42: dial tcp 192.0.2.1:9000: connection refused"), "connection_failed"}, + {errors.New("daemon: sendto: node 42 has no real address"), "connection_failed"}, + {errors.New("daemon: sendto: no tunnel to node 42"), "connection_failed"}, + {errors.New("daemon: sendto: pending queue full: newest packet dropped to preserve ordered prefix while key exchange pending"), "connection_failed"}, + {errors.New("daemon: sendto: too many pending key exchanges"), "connection_failed"}, + {errors.New("daemon: sendto: ephemeral ports exhausted"), "connection_failed"}, + {errors.New("daemon disconnected"), "connection_failed"}, + {driver.ErrConfirmTimeout, "timeout"}, + {driver.ErrConfirmQueueTimeout, "timeout"}, + {fmt.Errorf("send: %w", driver.ErrConfirmQueueTimeout), "timeout"}, + } { + if got := dgramErrorCode(tc.err); got != tc.want { + t.Errorf("dgramErrorCode(%q) = %s, want %s", tc.err, got, tc.want) + } + } +} + +// Through cmdDgram, with the daemon's answer: the code follows the reason. +func TestCmdDgramErrorCodes(t *testing.T) { + for refusal, want := range map[string]string{ + "sendto: port 7 not allowed by network 1 policy": "permission_denied", + "sendto: marshal: payload too large: 65536 bytes (max 65535)": "invalid_argument", + "sendto: resolve node 42: node 42: not found": "not_found", + "sendto: no tunnel to node 42": "connection_failed", + } { + t.Run(want, func(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + sd.dgramAnswer.Store(&refusal) + + var failure *trappedFatal + withJSON(func() { + _, _, failure = runTrapped(t, func() { + cmdDgram([]string{"0:0000.0000.002A", "9999", "--data", "udp-msg"}) + }) + }) + if failure == nil || failure.Code != want || !strings.Contains(failure.Message, refusal) { + t.Errorf("failure = %+v, want %s with the daemon's reason", failure, want) + } + }) + } +} + +// The daemon accepts at most 65535 bytes. A larger --data is refused before +// the daemon is contacted; it used to go to the daemon, which refused it as +// connection_failed. +func TestCmdDgramRefusesAnOversizeDatagram(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + var failure *trappedFatal + withJSON(func() { + _, _, failure = runTrapped(t, func() { + cmdDgram([]string{"0:0000.0000.002A", "9999", "--data", strings.Repeat("x", 65536)}) + }) + }) + if failure == nil || failure.Code != "invalid_argument" || !strings.Contains(failure.Message, "65535") { + t.Fatalf("failure = %+v, want invalid_argument naming the limit", failure) + } + sd.mu.Lock() + contacted := len(sd.received) + sd.mu.Unlock() + if contacted != 0 { + t.Errorf("the daemon got %d requests before the datagram was refused", contacted) + } + + // The largest payload the daemon accepts is passed on to it. + out := captureStdout(t, func() { + withJSON(func() { cmdDgram([]string{"0:0000.0000.002A", "9999", "--data", strings.Repeat("x", 65535)}) }) + }) + if !strings.Contains(out, `"bytes":65535`) || sd.dgramCount.Load() != 1 { + t.Errorf("65535-byte datagram: %s (daemon saw %d)", out, sd.dgramCount.Load()) } } @@ -798,6 +889,88 @@ func TestCmdBenchSmall(t *testing.T) { if data["sent_bytes"].(float64) < 1 { t.Errorf("sent_bytes = %v", data["sent_bytes"]) } + if data["complete"] != true || data["recv_bytes"] != data["sent_bytes"] { + t.Errorf("result = %v, want complete with everything echoed", data) + } +} + +// echoUpTo makes the daemon echo only the first n bytes written to each +// connection. With end, it then ends the stream, as a peer that closes it +// does; without, the stream stays open and silent. +func echoUpTo(sd *streamDaemon, n int, end bool) { + var mu sync.Mutex + echoed := map[uint32]int{} + sd.on(tdCmdSend, func(frame []byte) [][]byte { + if len(frame) < 5 { + return nil + } + connID, payload := frame[1:5], frame[5:] + mu.Lock() + defer mu.Unlock() + id := binary.BigEndian.Uint32(connID) + left := n - echoed[id] + if left <= 0 { + return nil + } + if len(payload) > left { + payload = payload[:left] + } + echoed[id] += len(payload) + out := [][]byte{append(append([]byte{tdCmdRecv}, connID...), payload...)} + if end && echoed[id] == n { + out = append(out, append([]byte{tdCmdCloseOK}, connID...)) + } + return out + }) +} + +// The echo stops short of what was sent. bench used to print "status":"ok" +// with 4096 of 10485 bytes received and a round-trip rate computed from the +// full size. It now fails, with the partial figures in the error: timeout +// when --timeout cut it, connection_failed when the echo stream ended. +func TestCmdBenchFailsOnAPartialEcho(t *testing.T) { + for name, tc := range map[string]struct { + end bool + code string + }{ + "cut by --timeout": {false, "timeout"}, + "echo stream closed": {true, "connection_failed"}, + } { + t.Run(name, func(t *testing.T) { + sd := newStreamDaemon(t) + sd.useDaemonNoRegistry(t) + echoUpTo(sd, 4096, tc.end) + fatalResults = nil + t.Cleanup(func() { fatalResults = nil }) + + var stderr string + var f *trappedFatal + withJSON(func() { + _, stderr, f = runTrapped(t, func() { cmdBench([]string{"0:0000.0000.002A", "0.01", "--timeout", "300ms"}) }) + }) + if f == nil || f.Code != tc.code || !strings.Contains(f.Message, "4.0 KB of 10.2 KB") { + t.Fatalf("bench = %+v, want %s naming what came back", f, tc.code) + } + results := errorResults(t, stderr) + if len(results) != 1 { + t.Fatalf("error results = %v, want the partial figures", results) + } + r := results[0] + if r["complete"] != false || r["sent_bytes"] != 10485.0 || r["recv_bytes"] != 4096.0 { + t.Fatalf("result = %v", r) + } + // The round-trip rate is what came back over the time it took + // (measurable here only when the wait ran to --timeout). + ms, _ := r["total_duration_ms"].(float64) + mbps, _ := r["total_mbps"].(float64) + if want := 4096.0 / (ms / 1000) / 1024 / 1024; ms >= 100 && (mbps < want*0.95 || mbps > want*1.05) { + t.Errorf("total_mbps = %v, want about %v (4096 bytes in %v ms)", mbps, want, ms) + } + if tc.code == "timeout" && ms < 300 { + t.Errorf("total_duration_ms = %v, want at least the 300ms --timeout", ms) + } + }) + } } func TestCmdBenchText(t *testing.T) {