diff --git a/app/src/main/kotlin/io/flamenet/messenger/app/CallManager.kt b/app/src/main/kotlin/io/flamenet/messenger/app/CallManager.kt index f5b91c7..5fead09 100644 --- a/app/src/main/kotlin/io/flamenet/messenger/app/CallManager.kt +++ b/app/src/main/kotlin/io/flamenet/messenger/app/CallManager.kt @@ -459,12 +459,17 @@ class CallManager( /** * A signal arrived down the ratchet. */ + init { + live = this + } + fun onSignal( fromUser: Long, incoming: Content.CallSignal, turn: JSONObject?, sentAt: Long = 0, ) { + live = this android.util.Log.i( "fnmsg-call", "call signal in: ${incoming.action} from $fromUser state=$state", @@ -517,8 +522,33 @@ class CallManager( renegotiate(fromUser, incoming, turn) return } - // One call at a time. + // The SAME call arriving again is not a second caller. + // + // Two loops poll one mailbox and they race on the inbox + // cursor, so an envelope fetched by one can still be handed to + // the other: measured, one offer on the relay and two + // deliveries here, 2.4 seconds apart. The second landed while + // this phone was ringing for the first, fell into the check + // below, and replied "busy" -- to the very call it was ringing + // for. The caller was told the callee was busy by a phone that + // was ringing at them. + // + // Closing the race is worth doing on its own, but a signal + // arriving twice has to be harmless whatever the transport + // does, so this is the check that belongs here. + if (incoming.callId == current?.callId) { + android.util.Log.i( + "fnmsg-call", + "offer for ${incoming.callId} again, already on it at state=$state", + ) + return + } + // One call at a time. A DIFFERENT call, now genuinely. if (state != State.IDLE && state != State.ENDED) { + android.util.Log.i( + "fnmsg-call", + "offer ${incoming.callId} answered busy: on ${current?.callId} at $state", + ) signal( fromUser, Content.CallSignal(Content.CallSignal.END, incoming.callId, reason = "busy"), @@ -540,10 +570,28 @@ class CallManager( } Content.CallSignal.ANSWER -> { - val sdp = incoming.sdp ?: return + val sdp = incoming.sdp + if (sdp == null) { + android.util.Log.i("fnmsg-call", "answer for ${incoming.callId} carried no sdp") + return + } // An answer for some earlier call, a retry raced a hang-up, // must not be installed into this one's connection. - if (incoming.callId != current?.callId) return + // + // This returned in silence, and a dropped answer looks from the + // outside exactly like an answer that never arrived: the caller + // sits on "Calling..." until the dial guard gives up 45 seconds + // later. Saying which id was expected is the difference between + // a minute of guessing and a line in the log. + if (incoming.callId != current?.callId) { + android.util.Log.i( + "fnmsg-call", + "answer for ${incoming.callId} ignored: current is " + + "${current?.callId} state=$state", + ) + return + } + android.util.Log.i("fnmsg-call", "answer accepted for ${incoming.callId}") peerRenegotiates = incoming.renegotiates dialGuard?.let { main.removeCallbacks(it) } dialGuard = null @@ -1048,6 +1096,43 @@ class CallManager( } companion object { + /** + * The call manager this process is using, if there is one. + * + * Two loops poll the same mailbox: the foreground one the view model + * drives, and the service's own, which keeps the mailbox watched while + * nothing is on screen. Whichever fetches an envelope first consumes + * it -- the relay marks it delivered and it is not handed out again. + * The service's handler knew what to do with an offer and an end and + * discarded everything else, so an ANSWER fetched by the service was + * simply thrown away. The caller then sat on "Calling..." for the full + * forty-five seconds and gave up, every time the race went that way. + * + * Registering here lets either loop hand a signal to the call that is + * actually up, instead of one of them holding the only route. + */ + @Volatile + @JvmStatic + var live: CallManager? = null + + /** + * Whether a call is being set up or is up right now. + * + * The poll loop asks this to decide how long it may let the relay hold + * a request open. Ordinarily twenty seconds is right and cheap. During + * a call it is the difference between an answer landing when it is sent + * and landing twenty seconds later, by which time the caller has + * watched "Calling..." for long enough to assume it is broken -- which + * is exactly what was measured: an offer at :07.9 and its answer + * accepted at :28.5. + */ + @JvmStatic + fun aCallIsUp(): Boolean = + when (live?.state) { + State.DIALLING, State.RINGING, State.CONNECTING, State.ACTIVE -> true + else -> false + } + /** How long an unanswered outgoing call rings before giving up. */ const val DIAL_TIMEOUT_MS = 45_000L diff --git a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt index 6ccbb26..4b1225c 100644 --- a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt +++ b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt @@ -78,7 +78,24 @@ class MessengerService : Service() { return START_STICKY } + /** + * The app was swiped out of Recents. + * + * The other end finds out on its own when the media stops, but that is + * several seconds of somebody holding a phone to their ear talking to a + * call that is already over. One envelope ends it at once. + * + * This runs before `onDestroy` and while the process is still alive, which + * is the whole reason to do it here: by the time the service is being torn + * down there may be no time to reach the network. + */ + override fun onTaskRemoved(rootIntent: android.content.Intent?) { + endAnyCallBeforeGoing() + super.onTaskRemoved(rootIntent) + } + override fun onDestroy() { + endAnyCallBeforeGoing() loop?.cancel() scope?.cancel() session?.onCallSignal = null @@ -86,6 +103,26 @@ class MessengerService : Service() { super.onDestroy() } + /** + * Hang up, if there is anything to hang up, before this process goes. + * + * Blocking, and deliberately: a coroutine launched here is cancelled with + * the scope a moment later and the envelope never leaves. Bounded so a + * relay that is not answering cannot hold up the teardown -- a call the far + * end works out for itself in a few seconds is much better than a service + * that will not die. + */ + private fun endAnyCallBeforeGoing() { + val manager = CallManager.live ?: return + if (!CallManager.aCallIsUp()) return + android.util.Log.i("fnmsg-call", "the app is going away during a call, telling the far end") + runCatching { + val worker = Thread { runCatching { manager.hangUp(notifyPeer = true) } } + worker.start() + worker.join(2_000) + } + } + private fun startInForeground() { val open = PendingIntent.getActivity( @@ -173,11 +210,52 @@ class MessengerService : Service() { Unit } } + // Whatever this loop made of it, a call that is actually up has to + // see it too. + // + // This loop and the view model's poll the same mailbox, and an + // envelope goes to whichever asks first: the relay marks it + // delivered and does not hand it out again. So every signal this + // handler did not forward was a signal the call never received. An + // ANSWER fell into `else` and was dropped, and the caller waited + // out its forty-five second dial guard for a reply that had already + // arrived and been thrown away. An END fared no better: it cleared + // a notification and left a live call running. + // + // Forwarding covers OFFER too, and costs nothing when it is a + // duplicate: the manager checks the call id and ignores what is not + // its own. + CallManager.live?.let { manager -> + runCatching { + manager.onSignal(fromUser, signal, s.turnCredentials(), sentAt) + }.onFailure { + android.util.Log.i( + "fnmsg-call", + "forwarding ${signal.action} from the service failed: $it", + ) + } + } } while (true) { val started = System.currentTimeMillis() - val touched = runCatching { s.receive(WAIT_SECONDS) }.getOrDefault(emptySet()) + // A call cannot wait on a twenty-second hold. + // + // Holding the request open is right for messages: it is one request + // per twenty seconds instead of forty, and a wake-up usually cuts + // it short anyway. It is wrong for a call, where the two signals + // that matter -- the answer and the hang-up -- are the ones somebody + // is watching a screen for. iOS polls hard for the length of a call + // and this never had the same thing, so an answer sent at once was + // accepted twenty seconds later and the caller had already decided + // nothing was happening. + // + // Ask, take what is there, go again. A request a second for the + // length of a call, and no worst case. + val onACall = CallManager.aCallIsUp() + val touched = + runCatching { s.receive(if (onACall) 0 else WAIT_SECONDS) } + .getOrDefault(emptySet()) if (touched.isNotEmpty()) notifyMessages(touched.size) // Reply reminders fire from THIS loop, after `receive()`, and the // order matters: an inbound message clears the reminder inside @@ -191,8 +269,12 @@ class MessengerService : Service() { // while was already the wait, and going straight back is what keeps // the mailbox continuously watched. Only a relay that answered at // once, one that has no hold to offer, gets paced. - val held = System.currentTimeMillis() - started >= 2_000 - if (!held) delay(500) + if (onACall) { + delay(1_000) + } else { + val held = System.currentTimeMillis() - started >= 2_000 + if (!held) delay(500) + } } } diff --git a/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt b/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt new file mode 100644 index 0000000..7afd4b0 --- /dev/null +++ b/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt @@ -0,0 +1,200 @@ +package io.flamenet.messenger.app + +import java.io.File +import org.junit.Assert.assertFalse +import org.junit.Assert.assertTrue +import org.junit.Test + +/** + * Two loops poll the same mailbox, and a signal must not be lost to whichever + * one happens to win. + * + * The service keeps the mailbox watched while nothing is on screen, and the + * view model polls while something is. An envelope goes to whichever asks + * first: the relay marks it delivered and does not hand it out again. The + * service's handler knew what to do with an offer and an end and had + * `else -> Unit` for the rest, so an ANSWER it happened to fetch was thrown + * away and the caller waited out the full forty-five second dial guard for a + * reply that had already arrived. + * + * Measured, not inferred: an iPhone answered, the relay accepted the answer, + * the Android side logged the envelope decrypting, and the call manager's own + * "call signal in" line never appeared. The signal reached the process and + * stopped one layer short of the call. + */ +class NoSignalIsEatenByTheServiceTest { + private fun source(path: String): String { + val file = File("src/main/kotlin/io/flamenet/messenger/app/$path") + assertTrue("missing $path", file.exists()) + return file.readText() + } + + private val service get() = source("MessengerService.kt") + private val manager get() = source("CallManager.kt") + + @Test + fun `the service hands every signal to a live call`() { + assertTrue( + "the service's handler drops anything it does not itself act on", + service.contains("CallManager.live?.let { manager ->"), + ) + assertTrue( + "forwarding has to carry what onSignal needs", + service.contains("manager.onSignal(fromUser, signal, s.turnCredentials(), sentAt)"), + ) + } + + /** + * Forwarding outside `when` and not inside one of its branches. Put in a + * branch it would cover only the actions somebody remembered, which is the + * bug restated. + */ + @Test + fun `forwarding is not itself inside the branch that dropped things`() { + val handler = service.substringAfter("s.onCallSignal = {").substringBefore("while (true)") + val forwardAt = handler.indexOf("CallManager.live") + val elseAt = handler.indexOf("else -> {") + assertTrue("no forwarding in the handler at all", forwardAt >= 0) + assertTrue("no else branch found", elseAt >= 0) + assertTrue( + "forwarding must run after the when, for every action", + forwardAt > elseAt, + ) + } + + /** A forward that throws must not take the poll loop down with it. */ + @Test + fun `forwarding cannot break the poll loop`() { + val handler = service.substringAfter("CallManager.live?.let { manager ->") + assertTrue( + "an exception here would kill the loop that watches the mailbox", + handler.take(400).contains("runCatching {"), + ) + } + + @Test + fun `a call registers itself so either loop can reach it`() { + assertTrue( + "nothing outside the view model could reach the call manager", + manager.contains("var live: CallManager?"), + ) + assertTrue( + "@Volatile, because the two loops are on different threads", + manager.contains("@Volatile\n @JvmStatic\n var live: CallManager?"), + ) + assertTrue("registered when built", manager.contains("init {\n live = this\n }")) + } + + /** + * The dropped answer returned in silence, which is indistinguishable from + * an answer that never arrived. It has to say which id it expected. + */ + @Test + fun `an ignored answer says why`() { + val answer = manager.substringAfter("Content.CallSignal.ANSWER -> {") + .substringBefore("Content.CallSignal.REACTION") + assertTrue( + "a silent return here costs an hour of guessing", + answer.contains("answer for \${incoming.callId} ignored: current is "), + ) + assertFalse( + "the bare silent return is the thing being fixed", + answer.contains("if (incoming.callId != current?.callId) return"), + ) + } + + /** + * The other half of the same complaint. Forwarding the answer is no use if + * it is fetched twenty seconds after it was sent. + * + * Measured: an offer went out at :07.9 and its answer was accepted at + * :28.5. The relay had it the whole time; this loop was inside a + * twenty-second hold and did not ask. + */ + @Test + fun `the poll does not hold a request open during a call`() { + assertTrue( + "the loop has to know a call is up before it can poll differently", + service.contains("val onACall = CallManager.aCallIsUp()"), + ) + assertTrue( + "a call polls with no hold at all", + service.contains("s.receive(if (onACall) 0 else WAIT_SECONDS)"), + ) + assertTrue( + "and paces itself, or it spins", + service.contains("if (onACall) {\n delay(1_000)"), + ) + } + + @Test + fun `every state a call passes through counts as being on a call`() { + val fn = manager.substringAfter("fun aCallIsUp()").substringBefore("}") + for (state in listOf("DIALLING", "RINGING", "CONNECTING", "ACTIVE")) { + assertTrue( + "$state has to poll hard: it is a state somebody is watching", + fn.contains(state), + ) + } + assertFalse("IDLE is not a call", fn.contains("State.IDLE,")) + } +} + +/** + * Closing the app during a call ends it on the other phone too. + * + * The far end does work it out on its own when the media stops, but that is + * several seconds of somebody holding a phone to their ear talking to a call + * that is already over. + */ +class ClosingTheAppEndsTheCallTest { + private fun source(path: String): String { + val file = File("src/main/kotlin/io/flamenet/messenger/app/$path") + assertTrue("missing $path", file.exists()) + return file.readText() + } + + private val service get() = source("MessengerService.kt") + + /** + * Swiping the app out of Recents calls this, and it runs while the process + * is still alive -- which is the point. By `onDestroy` there may be no time + * left to reach the network. + */ + @Test + fun `being swiped away ends the call`() { + assertTrue( + "nothing was listening for the app being swiped out of Recents", + service.contains("override fun onTaskRemoved(rootIntent: android.content.Intent?)"), + ) + assertTrue(service.contains("private fun endAnyCallBeforeGoing()")) + assertTrue( + "the end has to actually be sent, not just the call torn down here", + service.contains("manager.hangUp(notifyPeer = true)"), + ) + } + + /** + * On a thread with a join, not a coroutine: the scope is cancelled a moment + * later and a launched coroutine would be killed before the envelope left. + */ + @Test + fun `the hang up is not cancelled by the teardown it runs during`() { + val fn = service.substringAfter("private fun endAnyCallBeforeGoing()").take(700) + assertTrue( + "a coroutine here dies with the scope before the envelope is sent", + fn.contains("Thread {") && fn.contains("worker.join("), + ) + assertFalse( + "and it cannot block teardown for ever if the relay is not answering", + fn.contains("worker.join()"), + ) + } + + /** Only when there is a call, or the far end files a missed call for nothing. */ + @Test + fun `it does nothing when no call is up`() { + val fn = service.substringAfter("private fun endAnyCallBeforeGoing()").take(400) + assertTrue(fn.contains("if (!CallManager.aCallIsUp()) return")) + } +} diff --git a/client/src/main/kotlin/io/flamenet/client/RelayClient.kt b/client/src/main/kotlin/io/flamenet/client/RelayClient.kt index f970064..3bb3989 100644 --- a/client/src/main/kotlin/io/flamenet/client/RelayClient.kt +++ b/client/src/main/kotlin/io/flamenet/client/RelayClient.kt @@ -205,6 +205,20 @@ class RelayClient( data class ToDevice( val deviceId: String, val payload: String, + /** + * One id for this envelope, so the far side can tell a repeat from a + * second message. + * + * Both clients already refuse an envelope id they have seen before and + * neither ever sent one on this route, so every ordinary envelope + * reached the relay with a null id and the check on the other side + * could never fire. Envelopes DO arrive twice: two loops poll one + * mailbox and race on the inbox cursor. Measured -- one call offer on + * the relay, delivered twice 2.4 seconds apart, the second answered + * "busy" by the phone ringing for the first. Messages double the same + * way, more quietly. + */ + val envelopeId: String = java.util.UUID.randomUUID().toString(), ) { constructor(deviceId: String, envelope: Envelope) : this(deviceId, envelope.toPayload()) } @@ -258,7 +272,8 @@ class RelayClient( array.put( JSONObject() .put("to_device", it.deviceId) - .put("payload", it.payload), + .put("payload", it.payload) + .put("envelope_id", it.envelopeId), ) } }, diff --git a/client/src/test/kotlin/io/flamenet/client/EveryEnvelopeHasAnIdTest.kt b/client/src/test/kotlin/io/flamenet/client/EveryEnvelopeHasAnIdTest.kt new file mode 100644 index 0000000..b37049b --- /dev/null +++ b/client/src/test/kotlin/io/flamenet/client/EveryEnvelopeHasAnIdTest.kt @@ -0,0 +1,73 @@ +package io.flamenet.client + +import java.io.File +import kotlin.test.Test +import kotlin.test.assertFalse +import kotlin.test.assertTrue + +/** + * An envelope that arrives twice must be recognised as the same envelope. + * + * The de-duplication was already written on both sides and could never fire: + * it is guarded on the envelope id being non-empty, and nothing sent one on + * the ordinary route. The field existed only on the federated send, so every + * envelope on the relay had a null id. + * + * Envelopes do arrive twice. Two loops poll one mailbox and race on the inbox + * cursor. Measured: one call offer on the relay, two deliveries 2.4 seconds + * apart, the second answered "busy" by the phone that was ringing for the + * first. Messages and call log entries double the same way and more quietly. + */ +class EveryEnvelopeHasAnIdTest { + private fun source(path: String): String { + val file = File("src/main/kotlin/io/flamenet/client/$path") + assertTrue(file.exists(), "missing $path") + return file.readText() + } + + @Test + fun `an outgoing envelope carries an id`() { + val relay = source("RelayClient.kt") + assertTrue( + relay.contains("val envelopeId: String = java.util.UUID.randomUUID().toString()"), + "without a default every call site has to remember, and one will not", + ) + assertTrue( + relay.contains(""".put("envelope_id", it.envelopeId)"""), + "the id has to reach the wire, not just the data class", + ) + } + + /** + * The check on the way in is what the id is for, and it is guarded on the + * id being present -- which is exactly why a missing id failed silently + * rather than loudly. + */ + @Test + fun `an envelope seen before is dropped on the way in`() { + val conversations = source("Conversations.kt") + assertTrue(conversations.contains("if (message.envelopeId.isNotEmpty()) {")) + assertTrue(conversations.contains("if (vault.hasSeenEnvelope(message.envelopeId)) {")) + assertTrue( + conversations.contains("vault.rememberEnvelope(message.envelopeId)"), + "remembered, or the second copy is only dropped by luck", + ) + } + + /** The watermark still advances past a duplicate, or it is fetched for ever. */ + @Test + fun `a duplicate still advances the watermark`() { + val conversations = source("Conversations.kt") + val block = conversations.substringAfter("if (vault.hasSeenEnvelope(message.envelopeId)) {") + .take(400) + assertTrue( + block.contains("inboxWatermark = message.id") || + block.contains("setWatermarkFor(home, message.id)"), + "a skipped envelope that never advances is fetched for ever", + ) + assertFalse( + block.substringBefore("continue").contains("out.add"), + "and it must not be ingested anyway", + ) + } +}