transmit airtime fix

releasenotes/RELEASE_NOTES_1.17.4-zephcore.md

@@ -1,5 +1,7 @@
 # ZephCore 1.17.4-zephcore
 
+*Re-release: rebuilt to pick up the transmit-airtime fix listed at the end.*
+
 Storage housekeeping, plus a listen-before-talk fix. The repeater's `erase` never actually erased,
 a node flashed from another firmware could start out with somebody else's leftovers underneath it,
 and switching a node between companion and repeater firmware quietly let the two share the same
@@ -303,3 +305,8 @@ picks its own moments to reboot. Companions and observers were never affected.
 - **A wasted erase on the companion.** Running `erase` from the companion's USB console formatted the
   storage, then formatted it again on the reboot that followed, because the marker saying "this node
   has been set up" went out with everything else. Both paths behave the same way now.
+- **Transmit airtime read far too high, and drained the duty-cycle budget with it.** It was timed as
+  wall clock around each send, so channel checks and radio housekeeping counted as airtime — eight
+  times over on one repeater. It is now the packet's own airtime, the same figure received airtime has
+  always used, and the "packets sent" total can no longer disagree with the flood and direct counts
+  beneath it.

zephcore/adapters/radio/LoRaRadioBase.cpp

@@ -44,7 +44,7 @@ LoRaRadioBase::LoRaRadioBase(const struct device *lora_dev, MainBoard &board,
 			     NodePrefs *prefs)
 	: _loramac_node(false),
 	  _dev(lora_dev), _prefs(prefs), _board(&board),
-	  _in_recv_mode(0), _tx_active(0),
+	  _in_recv_mode(0), _tx_active(0), _tx_complete(0),
 	  _last_rssi(0), _last_snr(0),
 	  _rx_head(0), _rx_tail(0),
 	  _noise_floor(DEFAULT_NOISE_FLOOR), _calibration_threshold(0), _ema_unguarded(0),
@@ -174,12 +174,19 @@ void LoRaRadioBase::txWaitThreadFn(void *p1, void *p2, void *p3)
 				LOG_DBG("TX wait: signal already raised (result=%d)", result);
 			}
 			k_poll_signal_reset(&self->_tx_signal);
+			/* Latch the verdict BEFORE the RX re-arm below, not after:
+			 * onAfterTransmit() + startReceive() is a full modem
+			 * reconfigure over SPI, and any loop() pass that lands
+			 * inside it used to see "not complete yet" and abandon a
+			 * transmit that had in fact finished.  startSendRaw()'s
+			 * _tx_active CAS is what makes publishing the completion
+			 * this early safe. */
+			if (result >= 0) {
+				atomic_set(&self->_tx_complete, 1);
+			}
 			self->_board->onAfterTransmit();
 			self->startReceive();
 			atomic_set(&self->_tx_active, 0);
-			if (result >= 0) {
-				atomic_inc(&self->_packets_sent);
-			}
 			if (self->_tx_done_cb) {
 				self->_tx_done_cb(self->_tx_done_cb_user_data);
 			}
@@ -211,6 +218,11 @@ void LoRaRadioBase::txWaitThreadFn(void *p1, void *p2, void *p3)
 			k_poll_signal_check(&self->_tx_signal, &sig_state,
 					    &sig_result);
 			k_poll_signal_reset(&self->_tx_signal);
+			/* Latched ahead of the RX re-arm — see the equivalent
+			 * comment on the already-raised path above. */
+			if (sig_result >= 0) {
+				atomic_set(&self->_tx_complete, 1);
+			}
 			self->_board->onAfterTransmit();
 			self->startReceive();
 			atomic_set(&self->_tx_active, 0);
@@ -218,7 +230,6 @@ void LoRaRadioBase::txWaitThreadFn(void *p1, void *p2, void *p3)
 				LOG_ERR("TX failed: driver reported %d — packet lost",
 					sig_result);
 			} else {
-				atomic_inc(&self->_packets_sent);
 				LOG_INF("TX complete, RX restarted");
 			}
 
@@ -763,8 +774,24 @@ bool LoRaRadioBase::startSendRaw(const uint8_t *bytes, int len)
 		return false;
 	}
 
+	/* CAS, not a bare set: the wait thread publishes _tx_complete before it
+	 * re-arms RX, so the dispatcher can legitimately collect a completion
+	 * and come straight back here while that thread is still inside
+	 * startReceive().  A plain set would let this transmit be started and
+	 * then have its _tx_active cleared out from under it moments later --
+	 * and would leave the driver re-entering RX on top of a live TX.
+	 * Refusing instead is correct and cheap: the dispatcher re-queues and
+	 * the wind-down finishes in microseconds.  Placed before
+	 * onBeforeTransmit() so a refusal does not light the TX LED. */
+	if (!atomic_cas(&_tx_active, 0, 1)) {
+		LOG_DBG("startSendRaw: previous transmit still winding down");
+		return false;
+	}
+	/* A completion nobody collected belongs to the packet that just went
+	 * out, never to this one -- upstream's STATE_IDLE reset in the same
+	 * place. */
+	atomic_set(&_tx_complete, 0);
 	_board->onBeforeTransmit();
-	atomic_set(&_tx_active, 1);
 	_last_tx_start_ms = k_uptime_get_32();
 
 	/* Phase 2: when LBT is enabled, skip the pre-emptive hwCancelReceive()
@@ -827,7 +854,23 @@ bool LoRaRadioBase::startSendRaw(const uint8_t *bytes, int len)
 
 bool LoRaRadioBase::isSendComplete()
 {
-	return !atomic_get(&_tx_active);
+	/* One-shot, and it owns _packets_sent — the same contract as upstream's
+	 * RadioLibWrapper::isSendComplete(), which self-clears STATE_INT_READY
+	 * and does n_sent++ in the same breath.  Incrementing here rather than
+	 * in the wait thread is what keeps the radio's "packets sent" tally and
+	 * the dispatcher's flood/direct tallies in lockstep: both advance on
+	 * this one call, so a completion the dispatcher never collects (it hit
+	 * outbound_expiry first) is missed by both, exactly as upstream misses
+	 * it.  They used to be independent counters on independent threads,
+	 * which let "Total" and "Flood + Direct" disagree by thousands.
+	 *
+	 * This is a consuming call.  Anything that wants to know whether a
+	 * transmit is in flight must use isTxActive() instead. */
+	if (atomic_cas(&_tx_complete, 1, 0)) {
+		atomic_inc(&_packets_sent);
+		return true;
+	}
+	return false;
 }
 
 void LoRaRadioBase::onSendFinished()
@@ -875,9 +918,20 @@ bool LoRaRadioBase::isRadioReady()
 
 uint32_t LoRaRadioBase::getEstAirtimeFor(int len_bytes)
 {
-	uint8_t sf = _prefs ? _prefs->sf : LoRaConfig::SPREADING_FACTOR;
-	float bw = _prefs ? _prefs->bw : (float)LoRaConfig::BANDWIDTH;
-	uint8_t cr_val = _prefs ? _prefs->cr : LoRaConfig::CODING_RATE;
+	/* Read the params the radio is ACTUALLY running, not the saved prefs:
+	 * buildModemConfig() honours _has_radio_override, so a node under
+	 * `tempradio` transmits on the override preset while this used to
+	 * estimate for the stored one.  Everything downstream of the estimate
+	 * drifts with it — reported RX airtime, the TX airtime and duty-cycle
+	 * budget that now derive from it, and outbound_expiry.  Upstream cannot
+	 * drift this way because it asks the radio (getTimeOnAir()); these
+	 * accessors are our equivalent.  bw is read directly rather than via
+	 * getActiveBandwidthKHzX10(), whose fixed-point rounding would cost
+	 * precision at 31.25 kHz. */
+	uint8_t sf = getActiveSpreadingFactor();
+	float bw = _has_radio_override ? _override_bw
+		   : (_prefs ? _prefs->bw : (float)LoRaConfig::BANDWIDTH);
+	uint8_t cr_val = getActiveCodingRate();
 
 	if (sf < 6) sf = 6;
 	if (sf > 12) sf = 12;

zephcore/adapters/radio/LoRaRadioBase.h

@@ -116,7 +116,7 @@ public:
 	uint16_t getActivePreambleLength() const;
 	uint8_t getActiveSyncWord() const;
 	int8_t getConfiguredTxPower() const;
-	bool isTxActive() const { return atomic_get(&_tx_active) != 0; }
+	bool isTxActive() const override { return atomic_get(&_tx_active) != 0; }
 
 	/* Duty-cycle preamble false-positive counter.
 	 * Incremented by the driver whenever RX_TX_TIMEOUT fires in
@@ -314,6 +314,14 @@ protected:
 	MainBoard *_board;
 	atomic_t _in_recv_mode;
 	atomic_t _tx_active;
+	/* Completion latch: raised by the TX wait thread only on an affirmative
+	 * success verdict, consumed once by isSendComplete(), and cleared by
+	 * startSendRaw() so a completion the dispatcher never collected (it gave
+	 * up on outbound_expiry first) cannot leak into the next packet.  This
+	 * is the Zephyr equivalent of upstream's STATE_INT_READY -> STATE_IDLE
+	 * transition; _tx_active alone cannot serve, because it is also cleared
+	 * on every failure path and is read as a plain state query elsewhere. */
+	atomic_t _tx_complete;
 	volatile float _last_rssi;   /* word-aligned: atomic on ARM */
 	volatile float _last_snr;    /* word-aligned: atomic on ARM */
 

zephcore/include/mesh/Radio.h

@@ -18,7 +18,16 @@ public:
 	virtual uint32_t getEstAirtimeFor(int len_bytes) = 0;
 	virtual float packetScore(float snr, int packet_len) = 0;
 	virtual bool startSendRaw(const uint8_t *bytes, int len) = 0;
+	/* One-shot: returns true exactly once per completed transmit, and
+	 * consumes that completion.  Matches Arduino MeshCore's
+	 * RadioLibWrapper::isSendComplete(), which self-clears and owns the
+	 * packets-sent counter, so the radio's tally and the dispatcher's
+	 * flood/direct tallies can never drift apart.  Never call this as a
+	 * state query -- use isTxActive() for that. */
 	virtual bool isSendComplete() = 0;
+	/* Non-consuming "a transmit is in flight" query, for callers that want
+	 * the radio's state rather than the completion event. */
+	virtual bool isTxActive() const { return false; }
 	virtual void onSendFinished() = 0;
 
 	virtual int getNoiseFloor() const { return 0; }

zephcore/src/Dispatcher.cpp

@@ -124,7 +124,29 @@ void Dispatcher::loop()
 {
 	if (outbound) {
 		if (_radio->isSendComplete()) {
-			uint32_t t = (uint32_t)_ms->getMillis() - outbound_start;
+			/* Airtime is the modulation time of the packet that just
+			 * went out, not the wall-clock width of the send.
+			 *
+			 * Upstream measures the wall clock here and gets away with
+			 * it: on Arduino the CAD runs before outbound_start is
+			 * stamped, loop() polls continuously, and isSendComplete()
+			 * has no timeout, so almost nothing sits between the stamp
+			 * and the TX_DONE interrupt.  Our send has all three —
+			 * blocking LBT inside startSendRaw(), a wait-thread
+			 * watchdog, and event-driven completion — so the same
+			 * expression measured up to 8x the real airtime in the
+			 * field, and charged every millisecond of it to the
+			 * duty-cycle budget below.
+			 *
+			 * LoRa airtime is exact given SF/BW/CR/preamble/length, so
+			 * compute it rather than time it: same value the RX side
+			 * already accumulates, which makes the two figures on the
+			 * stats screen comparable for the first time, and the right
+			 * unit for tx_budget_ms, which is a transmitter-on-time
+			 * allowance (CAD is receiving, not transmitting). */
+			uint32_t t = _radio->getEstAirtimeFor(outbound->getRawLength());
+			LOG_DBG("TX complete: air=%ums wall=%ums", t,
+				(uint32_t)_ms->getMillis() - outbound_start);
 			total_air_time += t;
 			updateTxBudget();
 			if (t >= tx_budget_ms) {
@@ -165,7 +187,14 @@ void Dispatcher::maintenanceLoop()
 	 * on every role: the repeater/room-server "stats" CLI reply and binary
 	 * telemetry read _err_flags directly, the MQTT uplink publishes it, and
 	 * the companion returns it in its BLE device-status response. */
-	bool is_active = _radio->isInRecvMode() || !_radio->isSendComplete();
+	/* isTxActive(), not !isSendComplete(): the latter is now a one-shot that
+	 * consumes the completion, so asking it here would swallow the event the
+	 * dispatcher's own loop() is waiting to collect.  The value is identical
+	 * in every state — it is the same _tx_active read this line always
+	 * performed — so the spurious-STARTRX_TIMEOUT fix this term was added
+	 * for (rapid consecutive relays leaving radio_nonrx_start stale) is
+	 * unchanged. */
+	bool is_active = _radio->isInRecvMode() || _radio->isTxActive();
 	if (is_active != prev_isrecv_mode) {
 		prev_isrecv_mode = is_active;
 		if (!is_active) {
@@ -507,11 +536,20 @@ void Dispatcher::checkSend()
 			 * actual TX start (serialisation + logging can take 1-5 ms). */
 			bool final_is_receiving = _radio->isReceiving();
 			bool final_is_radio_ready = _radio->isRadioReady();
-			if (final_is_receiving || !final_is_radio_ready) {
+			/* isTxActive() covers the window the radio opened by
+			 * publishing its completion before it finishes re-arming
+			 * RX: we may have collected that completion and come
+			 * straight back here.  startSendRaw()'s CAS would refuse
+			 * anyway, but that refusal is reported as an LBT-busy
+			 * verdict and feeds the cad_busy_start escalation, which
+			 * this is not — "radio not ready yet" belongs here. */
+			if (final_is_receiving || !final_is_radio_ready ||
+			    _radio->isTxActive()) {
 				uint32_t retry = getCADFailRetryDelay();
-				LOG_DBG("checkSend: final gate blocked TX (isReceiving=%d, isRadioReady=%d, inRecvMode=%d)",
+				LOG_DBG("checkSend: final gate blocked TX (isReceiving=%d, isRadioReady=%d, inRecvMode=%d, txActive=%d)",
 					(int)final_is_receiving, (int)final_is_radio_ready,
-					(int)_radio->isInRecvMode());
+					(int)_radio->isInRecvMode(),
+					(int)_radio->isTxActive());
 				_mgr->queueOutbound(outbound, outbound_priority, futureMillis((int)retry));
 				outbound = nullptr;
 				if (_tx_queued_cb) {