Start Android capture and playback independently

tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioEngine.kt

@@ -40,9 +40,10 @@ class CallAudioEngine {
     }
 
     private val recordLock = Any()
+    private val trackLock = Any()
     private var audioRecord: AudioRecord? = null
     private var captureThread: Thread? = null
-    private var audioTrack: AudioTrack? = null
+    @Volatile private var audioTrack: AudioTrack? = null
     private var playThread: Thread? = null
     private var prevMode: Int = AudioManager.MODE_NORMAL
     private var prevSpeaker: Boolean = false
@@ -52,6 +53,9 @@ class CallAudioEngine {
 
     @Volatile private var active = false
     @Volatile private var callId = 0L
+    @Volatile private var captureReady = false
+    @Volatile private var playReady = false
+    private var duplexReady = false // только main
 
     @Volatile private var muted = false
 
@@ -73,7 +77,7 @@ class CallAudioEngine {
     fun isActive(): Boolean = active
 
     val diagnostics: String get() = synchronized(recordLock) {
-        "active=$active capture=$capFramesRead play=$playFramesWritten " +
+        "active=$active ready=$captureReady/$playReady capture=$capFramesRead play=$playFramesWritten " +
             "workers=${captureThread?.isAlive}/${playThread?.isAlive} " +
             "record=${audioRecord?.recordingState} track=${audioTrack?.playState} route=${router.route}"
     }
@@ -87,7 +91,7 @@ class CallAudioEngine {
 
     fun isMuted(): Boolean = muted
 
-    /** Запустить полнодуплекс для звонка. Возвращает true при успехе. */
+    /** Подготовить маршрут и запустить независимые RX/TX. Ошибки подготовки устройств приходят через onFailure. */
     fun start(id: Long): Boolean {
         stop()
         startElapsedMs = SystemClock.elapsedRealtime()
@@ -101,6 +105,7 @@ class CallAudioEngine {
         callId = id
         muted = false
         failed.set(false)
+        captureReady = false; playReady = false; duplexReady = false
         try {
             val ctx = ChatApplication.instance
             val am = ctx.getSystemService(Context.AUDIO_SERVICE) as AudioManager
@@ -128,82 +133,98 @@ class CallAudioEngine {
             capFramesRead = 0L
             syncAecForRoute(router.route)
 
-            // ── AudioRecord (захват) ──
             wiredActive = router.route == AudioRoute.HEADSET && router.wiredInputDevice() != null
             wantedWired = wiredActive
-            stageAt = SystemClock.elapsedRealtime()
-            audioRecord = createAudioRecord(wiredActive)
-            if (audioRecord == null) {
-                stop(); return false
-            }
-            val recordCreateMs = SystemClock.elapsedRealtime() - stageAt
-
-            /* Захват начинает отправку сразу; подготовка playback больше его не задерживает. */
             router.onInputDevice = { _ ->
                 wantedWired = router.route == AudioRoute.HEADSET && router.wiredInputDevice() != null
             }
-            active = true
-            captureElapsedMs = SystemClock.elapsedRealtime()
-            audioRecord?.startRecording()
-            if (audioRecord?.recordingState != AudioRecord.RECORDSTATE_RECORDING) {
-                LogManager.addLog("ERROR", "CallAudio", "capture not running id=$id record=${audioRecord?.recordingState}")
-                stop(); return false
-            }
-            val recordStartMs = SystemClock.elapsedRealtime() - captureElapsedMs
-            captureThread = Thread({ runWorker(id, "capture") { captureLoop() } }, "utun-call-capture").apply { start() }
-            LogManager.addLog("INFO", "CallAudio",
-                "capture started id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
-                    "nativeMs=$nativeMs modeMs=$modeMs routeMs=$routeMs recordCreateMs=$recordCreateMs recordStartMs=$recordStartMs")
-
-            // ── AudioTrack (воспроизведение) ──
-            stageAt = SystemClock.elapsedRealtime()
-            val trackMin = AudioTrack.getMinBufferSize(
-                SAMPLE_RATE, AudioFormat.CHANNEL_OUT_MONO, AudioFormat.ENCODING_PCM_16BIT)
-            if (trackMin <= 0) {
-                LogManager.addLog("ERROR", "CallAudio", "AudioTrack.getMinBufferSize=$trackMin id=$id")
-                stop(); return false
-            }
-            val trackBuf = (trackMin * 2).coerceAtLeast(FRAME_SAMPLES * 4)
-            audioTrack = try {
-                AudioTrack(
-                    AudioAttributes.Builder()
-                        .setUsage(AudioAttributes.USAGE_VOICE_COMMUNICATION)
-                        .setContentType(AudioAttributes.CONTENT_TYPE_SPEECH).build(),
-                    AudioFormat.Builder().setSampleRate(SAMPLE_RATE)
-                        .setEncoding(AudioFormat.ENCODING_PCM_16BIT)
-                        .setChannelMask(AudioFormat.CHANNEL_OUT_MONO).build(),
-                    trackBuf, AudioTrack.MODE_STREAM, AudioManager.AUDIO_SESSION_ID_GENERATE)
-            } catch (e: Exception) {
-                LogManager.addLog("ERROR", "CallAudio", "AudioTrack create failed: ${e.message}")
-                stop(); return false
-            }
-
-            if (audioTrack?.state != AudioTrack.STATE_INITIALIZED) {
-                LogManager.addLog("ERROR", "CallAudio", "AudioTrack not initialized id=$id")
-                stop(); return false
-            }
-
-            /* Прямое роутирование трека на выбранное устройство вывода (обход глючной
-               глобальной маршрутизации на ряде устройств). */
             router.onOutputDevice = { dev -> applyTrackOutputDevice(dev) }
-            applyTrackOutputDevice(router.currentOutputDevice)
-            val trackCreateMs = SystemClock.elapsedRealtime() - stageAt
 
-            stageAt = SystemClock.elapsedRealtime()
+            /* Замер AEC — через 300мс после готовности обоих направлений; RX этого не ждёт. */
-            audioTrack?.play()
+            val ready = Runnable {
-            if (audioTrack?.playState != AudioTrack.PLAYSTATE_PLAYING) {
+                if (callId == id && active && !failed.get() && captureReady && playReady && !duplexReady) {
-                LogManager.addLog("ERROR", "CallAudio", "playback not running id=$id track=${audioTrack?.playState}")
+                    duplexReady = true
-                stop(); return false
+                    mainHandler.postDelayed(aecDelayRunnable, 300)
+                    LogManager.addLog("INFO", "CallAudio", "duplex ready id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs}")
+                }
             }
-            val trackStartMs = SystemClock.elapsedRealtime() - stageAt
+            active = true
-            playThread = Thread({ runWorker(id, "play") { playLoop() } }, "utun-call-play").apply { start() }
 
-            /* Через ~300мс буферы устройства заполнены — замеряем реальную задержку AEC. */
+            // Каждый поток готовит только своё устройство. Отмена ждёт оба до release Android/native.
-            mainHandler.postDelayed(aecDelayRunnable, 300)
+            playThread = Thread({ runWorker(id, "play") {
+                synchronized(trackLock) {
+                    if (!active) return@runWorker
+                    val createdAt = SystemClock.elapsedRealtime()
+                    val trackMin = AudioTrack.getMinBufferSize(
+                        SAMPLE_RATE, AudioFormat.CHANNEL_OUT_MONO, AudioFormat.ENCODING_PCM_16BIT)
+                    if (trackMin <= 0) {
+                        reportFailure(id, "AudioTrack.getMinBufferSize=$trackMin")
+                        return@runWorker
+                    }
+                    val trackBuf = (trackMin * 2).coerceAtLeast(FRAME_SAMPLES * 4)
+                    val track = AudioTrack(
+                        AudioAttributes.Builder().setUsage(AudioAttributes.USAGE_VOICE_COMMUNICATION)
+                            .setContentType(AudioAttributes.CONTENT_TYPE_SPEECH).build(),
+                        AudioFormat.Builder().setSampleRate(SAMPLE_RATE).setEncoding(AudioFormat.ENCODING_PCM_16BIT)
+                            .setChannelMask(AudioFormat.CHANNEL_OUT_MONO).build(),
+                        trackBuf, AudioTrack.MODE_STREAM, AudioManager.AUDIO_SESSION_ID_GENERATE)
+                    audioTrack = track
+                    if (!active) return@runWorker
+                    if (track.state != AudioTrack.STATE_INITIALIZED) {
+                        reportFailure(id, "AudioTrack not initialized state=${track.state}")
+                        return@runWorker
+                    }
+                    applyTrackOutputDevice(router.currentOutputDevice)
+                    val trackCreateMs = SystemClock.elapsedRealtime() - createdAt
+                    val playedAt = SystemClock.elapsedRealtime()
+                    track.play()
+                    if (!active) return@runWorker
+                    if (track.playState != AudioTrack.PLAYSTATE_PLAYING) {
+                        reportFailure(id, "playback not running state=${track.playState}")
+                        return@runWorker
+                    }
+                    playReady = true
+                    LogManager.addLog("INFO", "CallAudio",
+                        "playback started id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
+                            "trackCreateMs=$trackCreateMs trackStartMs=${SystemClock.elapsedRealtime() - playedAt} " +
+                            "trackBuf=$trackBuf captureReady=$captureReady")
+                }
+                mainHandler.post(ready)
+                playLoop()
+            } }, "utun-call-play").apply { start() }
 
+            captureThread = Thread({ runWorker(id, "capture") {
+                synchronized(recordLock) {
+                    if (!active) return@runWorker
+                    val createdAt = SystemClock.elapsedRealtime()
+                    wiredActive = wantedWired
+                    val rec = createAudioRecord(wiredActive)
+                    audioRecord = rec
+                    if (!active) return@runWorker
+                    if (rec == null) {
+                        reportFailure(id, "AudioRecord create failed wired=$wiredActive")
+                        return@runWorker
+                    }
+                    val recordCreateMs = SystemClock.elapsedRealtime() - createdAt
+                    captureElapsedMs = SystemClock.elapsedRealtime()
+                    rec.startRecording()
+                    if (!active) return@runWorker
+                    if (rec.recordingState != AudioRecord.RECORDSTATE_RECORDING) {
+                        reportFailure(id, "capture not running state=${rec.recordingState}")
+                        return@runWorker
+                    }
+                    captureReady = true
+                    LogManager.addLog("INFO", "CallAudio",
+                        "capture started id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
+                            "recordCreateMs=$recordCreateMs recordStartMs=${SystemClock.elapsedRealtime() - captureElapsedMs} " +
+                            "playReady=$playReady")
+                }
+                mainHandler.post(ready)
+                captureLoop()
+            } }, "utun-call-capture").apply { start() }
             LogManager.addLog("INFO", "CallAudio",
-                "started id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
+                "preparing RX/TX independently id=$id totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} " +
-                    "trackCreateMs=$trackCreateMs trackStartMs=$trackStartMs wired=$wiredActive trackBuf=$trackBuf")
+                    "nativeMs=$nativeMs modeMs=$modeMs routeMs=$routeMs")
             return true
         } catch (e: Exception) {
             LogManager.addLog("ERROR", "CallAudio", "start failed id=$id: ${e.message}")
@@ -243,9 +264,11 @@ class CallAudioEngine {
                 catch (e: Exception) { LogManager.addLog("WARN", "CallAudio", "record stop failed id=$id: ${e.message}") }
             }
         }
-        audioTrack?.let { track ->
+        synchronized(trackLock) {
-            try { if (track.playState == AudioTrack.PLAYSTATE_PLAYING) track.pause() }
+            audioTrack?.let { track ->
-            catch (e: Exception) { LogManager.addLog("WARN", "CallAudio", "track pause failed id=$id: ${e.message}") }
+                try { if (track.playState == AudioTrack.PLAYSTATE_PLAYING) track.pause() }
+                catch (e: Exception) { LogManager.addLog("WARN", "CallAudio", "track pause failed id=$id: ${e.message}") }
+            }
         }
         playThread?.interrupt()
         captureThread?.join(); captureThread = null
@@ -258,6 +281,7 @@ class CallAudioEngine {
         try { audioTrack?.release() }
         catch (e: Exception) { LogManager.addLog("WARN", "CallAudio", "track release failed id=$id: ${e.message}") }
         audioTrack = null
+        captureReady = false; playReady = false; duplexReady = false
         NativeLib.callAudioStop()
         router.onOutputDevice = null
         router.onInputDevice = null
@@ -298,6 +322,7 @@ class CallAudioEngine {
                 return
             }
             var read = 0
+            val readAt = if (frame == 0L) SystemClock.elapsedRealtime() else 0L
             while (read < FRAME_SAMPLES) {
                 if (!active) return
                 // stop() разблокирует read до join; обычный захват не требует polling.
@@ -311,7 +336,8 @@ class CallAudioEngine {
             if (frame == 0L) {
                 val now = SystemClock.elapsedRealtime()
                 LogManager.addLog("INFO", "CallAudio",
-                    "first capture id=$callId totalMs=${now - startElapsedMs} recordToFrameMs=${now - captureElapsedMs}")
+                    "first capture id=$callId totalMs=${now - startElapsedMs} " +
+                        "recordToFrameMs=${now - captureElapsedMs} readMs=${now - readAt} playReady=$playReady")
             }
             /* диагностика: уровень захваченного сигнала (тишина vs звук) */
             if (sinceSwap < 10 || frame % 100L == 0L) {
@@ -381,6 +407,7 @@ class CallAudioEngine {
         val silence = ShortArray(FRAME_SAMPLES)
         val frameNs = FRAME_MS * 1_000_000L
         var nextNs = System.nanoTime()
+        var firstWrite = true
         while (active) {
             val track = audioTrack ?: return
             val n = NativeLib.callAudioPull(callId, buf)
@@ -413,6 +440,12 @@ class CallAudioEngine {
                 }
             }
 
+            if (firstWrite && active) {
+                firstWrite = false
+                LogManager.addLog("INFO", "CallAudio",
+                    "first playback write id=$callId totalMs=${SystemClock.elapsedRealtime() - startElapsedMs} captureReady=$captureReady")
+            }
+
             /* абсолютный deadline: не даём Thread.sleep накопить систематический дрейф
              * (важно для стабильного выравнивания рендер↔захват в AEC). */
             nextNs += frameNs
@@ -436,7 +469,7 @@ class CallAudioEngine {
     /** Замер реальной задержки рендер→захват и применение к AEC (один раз после старта). */
     private fun measureAecDelay() {
         synchronized(recordLock) {
-            if (!active) return
+            if (!active || !captureReady || !playReady) return
             val track = audioTrack ?: return
             val rec = audioRecord ?: return
             try {
@@ -474,13 +507,17 @@ class CallAudioEngine {
     }
 
     private fun applyTrackOutputDevice(dev: AudioDeviceInfo?) {
-        val track = audioTrack ?: return
+        synchronized(trackLock) {
-        if (dev == null) return
+            val track = audioTrack ?: return
-        try {
+            if (!active || dev == null) return
-            track.setPreferredDevice(dev)
+            val startedAt = SystemClock.elapsedRealtime()
-            LogManager.addLog("DEBUG", "CallAudio", "track preferred device -> type=${dev.type}")
+            try {
-        } catch (e: Exception) {
+                val ok = track.setPreferredDevice(dev)
-            LogManager.addLog("WARN", "CallAudio", "setPreferredDevice failed: ${e.message}")
+                LogManager.addLog(if (ok) "INFO" else "WARN", "CallAudio",
+                    "track preferred device type=${dev.type} accepted=$ok totalMs=${SystemClock.elapsedRealtime() - startedAt}")
+            } catch (e: Exception) {
+                LogManager.addLog("WARN", "CallAudio", "setPreferredDevice failed: ${e.message}")
+            }
         }
     }
 }

tools/chatgui-android/app/src/main/java/com/utun/chat/data/CallAudioRouter.kt

@@ -96,20 +96,29 @@ class CallAudioRouter {
             override fun onAudioDevicesAdded(addedDevices: Array<out AudioDeviceInfo>?) = onDevicesChanged()
             override fun onAudioDevicesRemoved(removedDevices: Array<out AudioDeviceInfo>?) = onDevicesChanged()
         }
+        var stageAt = SystemClock.elapsedRealtime()
         am.registerAudioDeviceCallback(cb, Handler(Looper.getMainLooper()))
         deviceCallback = cb
+        val callbackMs = SystemClock.elapsedRealtime() - stageAt
 
+        stageAt = SystemClock.elapsedRealtime()
         bindBtHeadsetProfile()
+        val btProfileMs = SystemClock.elapsedRealtime() - stageAt
 
         val devicesAt = SystemClock.elapsedRealtime()
         devices = am.getDevices(AudioManager.GET_DEVICES_ALL)
         val devicesMs = SystemClock.elapsedRealtime() - devicesAt
         hasEarpiece = findBuiltinEarpiece() != null
         route = if (autoHeadset) (if (isHeadsetConnected()) AudioRoute.HEADSET else fallbackRoute) else preferredRoute
+        stageAt = SystemClock.elapsedRealtime()
         applyRoute(route)
+        val applyMs = SystemClock.elapsedRealtime() - stageAt
+        stageAt = SystemClock.elapsedRealtime()
         refresh()
+        val refreshMs = SystemClock.elapsedRealtime() - stageAt
         LogManager.addLog("INFO", "CallAudioRouter",
-            "started totalMs=${SystemClock.elapsedRealtime() - startedAt} devicesMs=$devicesMs " +
+            "started totalMs=${SystemClock.elapsedRealtime() - startedAt} callbackMs=$callbackMs btProfileMs=$btProfileMs " +
+                "devicesMs=$devicesMs applyMs=$applyMs refreshMs=$refreshMs " +
                 "devices=${devices?.size} hasEarpiece=$hasEarpiece autoHeadset=$autoHeadset fallback=$fallbackRoute")
     }
 
@@ -172,6 +181,7 @@ class CallAudioRouter {
 
     /* ── применение маршрута ── */
     private fun applyRoute(r: AudioRoute) {
+        val startedAt = SystemClock.elapsedRealtime()
         try {
             var dev: AudioDeviceInfo? = null
             var inDev: AudioDeviceInfo? = null
@@ -235,7 +245,8 @@ class CallAudioRouter {
             onInputDevice?.invoke(inDev)
             LogManager.addLog("INFO", "CallAudioRouter",
                 "route -> $r dev=${dev?.type}/${dev?.productName ?: "-"} inDev=${inDev?.type ?: "-"} " +
-                    "preferWired=$preferWiredHeadset mode=${am.mode} speaker=${am.isSpeakerphoneOn}")
+                    "preferWired=$preferWiredHeadset mode=${am.mode} speaker=${am.isSpeakerphoneOn} " +
+                    "totalMs=${SystemClock.elapsedRealtime() - startedAt}")
         } catch (e: Exception) {
             LogManager.addLog("ERROR", "CallAudioRouter", "applyRoute $r failed: ${e.message}")
         }