Skip to content

MQTT never recovers from ERROR state after a network change #2294

Description

@tobru

Environment

  • Version: 2.6.0-beta1 (git describe: v2.6.0-beta1-18-g4d63fa9d), MQTT mode, GMS flavour
  • Android: 17 / device: Pixel 10 Pro
  • Battery optimisation: not exempt (isIgnoringBatteryOptimizations=false, from PowerStateLogger)

Symptom

After a connectivity change (WLAN ↔ WLAN, WLAN ↔ mobile) the app sometimes stops publishing and never reconnects. Status screen shows:

  • Endpunktstatus / endpoint state: Fehler (ERROR)
  • Endpunkt-Statusnachricht: Unbekannter Host (UnknownHostException)

It stays that way indefinitely, subsequent network changes do not recover it.
Stopping and starting the app fixes it immediately.

Evidence

What the steady state shows:

Log line Count
MessageProcessor$queueMessageForSending: Queueing message=… 77
RoomBackedMessageQueue: Enqueued message with sequence … 77
RoomBackedMessageQueue: Dequeued message with id … 0
MessageProcessor: Taken message off queue: … 0
MQTTMessageProcessorEndpoint: Sending message … 0
MessageProcessor: Waiting for … before retrying send 0
Scheduler: Scheduled ONETIME_TASK_MQTT_RECONNECT job 0
MQTTReconnectWorker: MQTT reconnect worker job started 0
any MQTTMessageProcessorEndpoint line at all 0

queueLength grew 5185 → 5261 over the window (~456 msg/h), so the backlog of 5185 represents roughly 11 hours of failing to send. The BackgroundService was alive the whole time (location callbacks every 15 s).

Two independent things are therefore broken.


Defect A: nothing retries the connection once the state is ERROR

Complete list of code paths that can (re)start an MQTT connection:

  1. MQTTMessageProcessorEndpoint.activate() — once, when the endpoint is loaded
  2. NetworkTrackingCallback.onAvailable — see below
  3. NetworkTrackingCallback.onLost (for the current network) — disconnect + scheduleMqttReconnect()
  4. mqttCallback.connectionLost — DISCONNECTED + scheduleMqttReconnect()
  5. onPreferenceChanged for a handful of preferences
  6. MQTTReconnectWorker (WorkManager)
  7. the manual reconnect menu item

A1. onAvailable only retries when the state is exactly DISCONNECTED

project/app/src/main/kotlin/org/owntracks/android/net/mqtt/NetworkTrackingCallback.kt:41-52

if (network != currentNetwork) {
  currentNetwork = network
  reconnectFunction()
} else if (endpointState() == EndpointState.DISCONNECTED) {
  reconnectFunction()
}

A failed connect leaves the state at ERROR (MQTTMessageProcessorEndpoint.kt:437), not DISCONNECTED. So once a connect
attempt has failed, every later onAvailable for the same Network object is a no-op. This is exactly the case that matters: Wi‑Fi associates, onAvailable fires, DNS is not usable yet, connect fails with UnknownHostException → ERROR; the network becomes properly usable seconds later (validation completes, DHCP/DNS settles, VPN comes up) and the framework does not hand out a new Network, so nothing ever retries.

The guard should cover ERROR / ERROR_CONFIGURATION / INITIAL / IDLE / CONNECTING — i.e. anything that is not CONNECTED — not just DISCONNECTED.

A2. onAvailable reconnects immediately, before the network is usable

onAvailable is delivered when a network is available, not when it is validated and routable. The reconnect fires straight away with no delay and no retry of its own, and DNS on a just-arrived network commonly fails at that instant — which is precisely the UnknownHostException observed.

The WorkManager path deliberately waits (Scheduler.RECONNECT_DELAY_SECONDS = 10, comment: "Pause in case there's network turmoil"), but the onAvailable path does not. Waiting for NET_CAPABILITY_VALIDATED via onCapabilitiesChanged, or at least debouncing, would avoid burning the one and only reconnect attempt on a network that isn't ready yet.

A3. Sockets/DNS are never bound to the Network that triggered the reconnect

NetworkTrackingCallback receives the Network object but only ever uses it fo identity comparison. There is no Network.bindSocket(), ConnectivityManager.bindProcessToNetwork(), or Network.getSocketFactory() anywhere in the codebase (grep for bindSocket|bindProcessToNetwork|setProcessDefaultNetwork returns nothing). During a switch the process-default network can still be the
old, dead one when the reconnect runs, which again produces UnknownHostException.

A4. The WorkManager fallback backs off to hours

Scheduler.scheduleMqttReconnect() uses BackoffPolicy.EXPONENTIAL with MIN_BACKOFF_MILLIS (10 s) and MQTTReconnectWorker returns Result.retry() on failure. WorkManager caps at MAX_BACKOFF_MILLIS = 5 hours: 10 s, 20 s, 40 s, … 43 min, 85 min, 2.8 h, 5 h. Reaching the cap takes under 6 hours of failures. After that, with NetworkType.CONNECTED constraints plus Doze/App Standby deferral on a device that is not battery-optimisation exempt, retries are effectively unbounded. This is consistent with an 11-hour backlog and zero MQTT reconnect worker job started lines in a 10-minute window.

Also note MQTTReconnectWorker returns Result.failure() — terminal, never retried — when messageProcessor.isEndpointReady is false.

A5. There is no health check

StatefulServiceMessageProcessor.checkConnection() is implemented (MQTTMessageProcessorEndpoint.kt:469) but has no callers anywhere in the codebase. Nothing periodically verifies the connection or notices that the outgoing queue has been growing for hours. isAutomaticReconnect = false (MQTTConnectionConfiguration.kt:68) so Paho's own reconnect is off too — the app owns 100% of the reconnect responsibility, with the gaps above.


Defect B: the outgoing message loop is dead and can never be restarted

Independent of the connection state, the send loop is not running at all. With state ERROR, a live loop would take a message off the queue, get
NotConnectedException from MQTTMessageProcessorEndpoint.sendMessage (:192-194), and log W MQTT not connected for message … Re-queueing + D Waiting for … before retrying send at least every 2 minutes (SEND_FAILURE_BACKOFF_MAX_WAIT = 2.minutes). Over 10
minutes there are zero such lines and zero dequeues against 77 enqueues.

B1. initialize() is a one-shot, but stopSendingMessages() is not

MessageProcessor is @Singleton (application scope); BackgroundService is not.

// MessageProcessor.kt:94,122-136
private var initialized = false            // never reset
fun initialize() {
  if (!initialized) { … loadOutgoingMessageProcessor(); initialized = true }
}

// MessageProcessor.kt:567-570  ← called from BackgroundService.onDestroy():251
fun stopSendingMessages() { dequeueAndSenderJob?.cancel() }

If the service is destroyed while the process survives, dequeueAndSenderJob is cancelled, the loop breaks on CancellationException
(MessageProcessor.kt:350-353) and exits. The service is then recreated (START_STICKY, or the activity restarting it — visible in the log at 00:12:27 and 00:12:32 as no intent or action provided, setting up location request…), setupAndStartService() calls messageProcessor.initialize() (BackgroundService.kt:367), and it is a no-op because initialized is still true. The sender job is never relaunched.

The only other caller of loadOutgoingMessageProcessor() is onPreferenceChanged for the queue-wiping preferences. MessageProcessor.reconnect() — the path used by the network callback, the reconnect worker and the UI button — reconnects MQTT
but never re-arms the sender loop.

Net effect: queue grows forever, nothing is ever published, and only killing the process (fresh singleton) recovers. Matches "restarting the app fixes it".

B2. The recovery path is guarded by a racy isLocked check

// MessageProcessor.kt:245-249
private suspend fun sendAvailableMessages() {
  if (outboundMessageQueueMutex.isLocked) {
    Timber.d("Outbound message loop already running. Skipping.")
    return
  }

If a previous loop is blocked while holding the mutex, every future attempt to start a loop silently returns — including the loadOutgoingMessageProcessor() recovery path. Mutex.isLocked is also TOCTOU-racy as a "is a loop alive" test; dequeueAndSenderJob?.isActive is the real question.

B3. Alternative/additional blocking point

MQTTMessageProcessorEndpoint.kt:209-213

while (mqttClient.inFlightMessageCount >= mqttConnectionConfiguration.maxInFlight) {
  Timber.v("Pausing to wait for inflight to drop below max")
  delay(100.milliseconds)
}

Unbounded, and logged only at V (the exported log is D), so a loop stuck here is completely invisible. sendMessage captures mqttClientAndConfiguration at entry, so a reconnect swapping in a new client does not release a loop spinning on the old one. Worth a deadline regardless of whether it is what happened here.


Secondary observations

  • EndpointState is an enum carrying mutable message/error fields, and withError() mutates the shared enum constant. EndpointStateRepo.endpointState is a MutableStateFlow, which conflates equal values — so an ERROR → ERROR transition with a different cause emits nothing and the displayed error message can be stale. It is also shared mutable global state across endpoints and threads.
  • ScopeModule.providesCoroutineScope is @Provides without @Singleton, so every injection site receives its own CoroutineScope. MessageProcessor and MQTTMessageProcessorEndpoint do not share a scope, which makes the cancellation semantics around retryDelayJob / dequeueAndSenderJob harder to reason about than they look.
  • Diagnosability: at D level a 500-entry buffer is exhausted in ~10 minutes by routine location/geocoder logging, so by the time a user notices and exports, every connection-related line is gone. Connection lifecycle events (endpoint state transitions, service destroy, sender-loop start/exit, reconnect scheduling) are mostly V. Logging those at I/W, and/or a larger or level-partitioned buffer, would make this class of bug reportable.

Suggested directions

  1. NetworkTrackingCallback: retry on any non-CONNECTED state, not only DISCONNECTED.
  2. Trigger the reconnect on validated capability rather than raw onAvailable, and/or debounce it; failing that, always schedule the WorkManager fallback after an onAvailable-driven attempt fails.
  3. Bind the MQTT socket/DNS to the Network the callback handed you.
  4. Cap the reconnect backoff (a periodic worker, or reset the unique work so the exponential chain restarts) so it can never grow to hours.
  5. Make the sender loop lifecycle idempotent: restart dequeueAndSenderJob when it is not active, drive it from reconnect() as well, and replace the isLocked guard with a real liveness check.
  6. Call checkConnection() from somewhere — e.g. a watchdog that reconnects when the queue has been non-empty and unchanged for N minutes.

Disclaimer

I debugged this issue using Claude Code Opus 5 with logs I collected on my device and observations I made. This way I could steer Claude in the right direction. I hope this helps to finally solve this issue which is nagging me since a long time.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions