diff --git a/Deploy/PRODUCTION_SERVERS.md b/Deploy/PRODUCTION_SERVERS.md index 77f98af..a752eed 100644 --- a/Deploy/PRODUCTION_SERVERS.md +++ b/Deploy/PRODUCTION_SERVERS.md @@ -2,14 +2,19 @@ ## Короткий ответ -По текущим данным репозитория у SHiNE формально описан **один production-хост**: +По текущим данным репозитория у SHiNE описаны **два production-контура**: - `player@shineup.me` - домен `shineup.me` - IP `185.229.109.118` -Второй отдельный production-хост в текущих проектных инструкциях **не описан**. -Остальные известные серверы в репозитории относятся к test-контурам. +и + +- `player@193.8.215.70` +- домен `t.shineup.me` +- IP `193.8.215.70` + +Отдельно резервный хост `test.shineup.me` сейчас помечен как временно неработающий. ## 1. Основной production-хост @@ -47,7 +52,29 @@ Deploy: - любые изменения на `shineup.me` делать только после отдельного подтверждения пользователя. -## 2. Связанные публичные production-публикации на том же хосте +## 2. Второй production-сервер + +- SSH: `player@193.8.215.70` +- домен: `t.shineup.me` +- IP: `193.8.215.70` +- пользователь: `player` +- базовый путь: `/home/player` + +Роль: + +- второй production-контур SHiNE; +- использовать как production-сервер, несмотря на исторические имена deploy-задач + `deployServerTest2` / `deployUITest2`. + +Основные каталоги: + +- проект SHiNE: `/home/player/SHiNE` +- серверный jar: `/home/player/SHiNE/shine-server/shine-server.jar` +- UI: `/home/player/SHiNE/shine-ui` +- данные: `/home/player/SHiNE/shine-server/data/` +- логи: `/home/player/SHiNE/shine-server/logs/app.log` + +## 3. Связанные публичные production-публикации на том же хосте На этом же production-хосте есть отдельная публикация для `shine_payments`: @@ -58,15 +85,12 @@ Deploy: Это не второй production-хост SHiNE, а отдельный сайт на том же сервере. -## 3. Какие серверы не считать production +## 4. Какие серверы не считать production Не production: -- `t.shineup.me` (`193.8.215.70`) — основной test -- `test.shineup.me` (`93.170.12.154`) — резервный test +- `test.shineup.me` (`93.170.12.154`) — резервный хост, временно не работает - `t1.shineup.me` - `t2.shineup.me` - `t3.shineup.me` - `t4.shineup.me` - -Если позже появится второй отдельный production-хост, его нужно явно добавить в этот файл. diff --git a/Deploy/README.md b/Deploy/README.md index a7d0b34..daaad5a 100644 --- a/Deploy/README.md +++ b/Deploy/README.md @@ -15,11 +15,11 @@ - `player@shineup.me` - домен `shineup.me` - IP `185.229.109.118` -- Main test: +- Второй production SHiNE: - `player@193.8.215.70` - домен `t.shineup.me` - IP `193.8.215.70` -- Reserve test: +- Временно неработающий резервный test: - `player@93.170.12.154` - домен `test.shineup.me` - IP `93.170.12.154` @@ -35,6 +35,7 @@ ## Важно -- Формально production-хост SHiNE в текущем репозитории описан один: `shineup.me`. -- `t.shineup.me`, `test.shineup.me`, `t1..t4.shineup.me` — это тестовые контуры, не production. +- Production-контура SHiNE сейчас два: `shineup.me` и `t.shineup.me`. +- `test.shineup.me` сейчас помечен как временно неработающий резервный test-хост. +- `t1..t4.shineup.me` — это отдельные тестовые/devnet-контуры, не production. - Любые изменения на `shineup.me` делать только после отдельного подтверждения пользователя. diff --git a/Deploy/TEST_SERVERS.md b/Deploy/TEST_SERVERS.md index 5b32d70..8ef01af 100644 --- a/Deploy/TEST_SERVERS.md +++ b/Deploy/TEST_SERVERS.md @@ -2,12 +2,12 @@ Этот файл описывает тестовые контуры, которые сейчас фигурируют в проекте. -## 1. Основной test-сервер +## 1. Исторический `test2`, теперь второй production-сервер - SSH: `player@193.8.215.70` - Домен: `t.shineup.me` - IP: `193.8.215.70` -- Назначение: основной test для обычных `deployServer` / `deployUI` +- Назначение: второй production-контур SHiNE Структура: @@ -31,11 +31,11 @@ Deploy: Примечания: -- это основной тестовый контур; -- default deploy по проекту должен идти сюда; -- тестовая БД синхронизируется от production `shineup.me`. +- этот хост больше не считать test-контуром; +- исторические имена deploy-задач `deployServerTest2` / `deployUITest2` сохранены, но сам хост считать production; +- при описании окружений перечислять его как второй production-сервер. -## 2. Резервный test-сервер +## 2. Резервный test-сервер, временно неработающий - SSH: `player@93.170.12.154` - Домен: `test.shineup.me` @@ -58,6 +58,7 @@ Deploy: Примечания: - этот хост резервный; +- сейчас помечен как временно неработающий; - использовать его без отдельной причины не нужно. ## 3. Отдельный quad-devnet стенд `t1..t4` diff --git a/SHiNE-server/shine-server-net-protocol/src/main/java/server/logic/ws_protocol/JSON/messages/Net_CallSignalToSession_Handler.java b/SHiNE-server/shine-server-net-protocol/src/main/java/server/logic/ws_protocol/JSON/messages/Net_CallSignalToSession_Handler.java index d065f7e..60ec4df 100644 --- a/SHiNE-server/shine-server-net-protocol/src/main/java/server/logic/ws_protocol/JSON/messages/Net_CallSignalToSession_Handler.java +++ b/SHiNE-server/shine-server-net-protocol/src/main/java/server/logic/ws_protocol/JSON/messages/Net_CallSignalToSession_Handler.java @@ -2,6 +2,8 @@ package server.logic.ws_protocol.JSON.messages; import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.databind.node.ObjectNode; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import server.logic.ws_protocol.JSON.ActiveConnectionsRegistry; import server.logic.ws_protocol.JSON.ConnectionContext; import server.logic.ws_protocol.JSON.entyties.Net_Request; @@ -24,6 +26,7 @@ import java.util.List; import java.util.Set; public class Net_CallSignalToSession_Handler implements JsonMessageHandler { + private static final Logger log = LoggerFactory.getLogger(Net_CallSignalToSession_Handler.class); private static final ObjectMapper MAPPER = new ObjectMapper(); private static final int TYPE_ACCEPT = 120; private static final int TYPE_DECLINE_BUSY = 130; @@ -55,28 +58,15 @@ public class Net_CallSignalToSession_Handler implements JsonMessageHandler { ConnectionContext targetCtx = ActiveConnectionsRegistry.getInstance().getBySessionId(targetSessionId); if (targetCtx == null || !to.equalsIgnoreCase(targetCtx.getLogin())) { - // Fallback: если точной сессии уже нет (переподключение), но у пользователя ровно 1 активная сессия, - // отправляем в неё, чтобы не ронять звонок из-за устаревшего targetSessionId. - Set activeForLogin = ActiveConnectionsRegistry.getInstance().getByLogin(to); - if (activeForLogin.size() == 1) { - targetCtx = activeForLogin.iterator().next(); - } else { - return NetExceptionResponseFactory.error(req, 404, "SESSION_NOT_FOUND", "Целевая сессия не найдена"); - } + logSessionNotFound(ctx, to, targetSessionId, callId, type, "target_ctx_missing_or_login_mismatch"); + return NetExceptionResponseFactory.error(req, 404, "SESSION_NOT_FOUND", "Целевая сессия не найдена"); + } + boolean delivered = sendSignalEvent(targetCtx, ctx.getLogin(), ctx.getSessionId(), to, callId, type, data); + String deliveredSessionId = String.valueOf(targetCtx.getSessionId() == null ? "" : targetCtx.getSessionId()).trim(); + if (!delivered) { + logSessionNotFound(ctx, to, targetSessionId, callId, type, "target_ws_not_delivered"); + return NetExceptionResponseFactory.error(req, 404, "SESSION_NOT_FOUND", "Целевая сессия не найдена"); } - - String eventId = NetIdGenerator.eventId("evt"); - ObjectNode payload = MAPPER.createObjectNode(); - payload.put("eventId", eventId); - payload.put("fromLogin", ctx.getLogin()); - payload.put("fromSessionId", ctx.getSessionId()); - payload.put("toLogin", to); - payload.put("callId", callId); - payload.put("type", type); - payload.put("data", data); - payload.put("timeMs", System.currentTimeMillis()); - - boolean delivered = WsEventSender.sendEvent(targetCtx, "IncomingCallSignal", eventId, payload); if (type == TYPE_ACCEPT) { notifyStopOnOtherSessions( @@ -101,7 +91,7 @@ public class Net_CallSignalToSession_Handler implements JsonMessageHandler { ); notifyStopOnOtherSessions( to, - targetCtx.getSessionId(), + deliveredSessionId, ctx.getLogin(), ctx.getSessionId(), callId, @@ -177,10 +167,61 @@ public class Net_CallSignalToSession_Handler implements JsonMessageHandler { } } + private boolean sendSignalEvent( + ConnectionContext targetCtx, + String fromLogin, + String fromSessionId, + String toLogin, + String callId, + int type, + String data + ) throws Exception { + if (targetCtx == null || targetCtx.getWsSession() == null || !targetCtx.getWsSession().isOpen()) { + return false; + } + String eventId = NetIdGenerator.eventId("evt"); + ObjectNode payload = MAPPER.createObjectNode(); + payload.put("eventId", eventId); + payload.put("fromLogin", fromLogin); + payload.put("fromSessionId", fromSessionId); + payload.put("toLogin", toLogin); + payload.put("callId", callId); + payload.put("type", type); + payload.put("data", data); + payload.put("timeMs", System.currentTimeMillis()); + return WsEventSender.sendEvent(targetCtx, "IncomingCallSignal", eventId, payload); + } + private boolean isBlank(String s) { return s == null || s.isBlank(); } + private void logSessionNotFound( + ConnectionContext fromCtx, + String toLogin, + String targetSessionId, + String callId, + Integer type, + String reason + ) { + int activeSessionsCount = 0; + try { + activeSessionsCount = ActiveConnectionsRegistry.getInstance().getByLogin(toLogin).size(); + } catch (Exception ignored) { + } + log.warn( + "CALL_SIGNAL_SESSION_NOT_FOUND fromLogin={} fromSessionId={} toLogin={} targetSessionId={} callId={} type={} activeSessionsCount={} reason={}", + fromCtx != null ? String.valueOf(fromCtx.getLogin()) : "", + fromCtx != null ? String.valueOf(fromCtx.getSessionId()) : "", + String.valueOf(toLogin), + String.valueOf(targetSessionId), + String.valueOf(callId), + type == null ? "" : String.valueOf(type), + activeSessionsCount, + String.valueOf(reason) + ); + } + private static String jsonEscape(String s) { if (s == null) return ""; StringBuilder out = new StringBuilder(); diff --git a/VERSION.properties b/VERSION.properties index de7e598..5ded630 100644 --- a/VERSION.properties +++ b/VERSION.properties @@ -1,2 +1,2 @@ -client.version=1.2.311 -server.version=1.2.290 +client.version=1.2.312 +server.version=1.2.291 diff --git a/docs/Pending_Features/2026-07-14_1325_fix_call_remote_hangup_and_ack_timeout.md b/docs/Pending_Features/2026-07-14_1325_fix_call_remote_hangup_and_ack_timeout.md new file mode 100644 index 0000000..d81fe49 --- /dev/null +++ b/docs/Pending_Features/2026-07-14_1325_fix_call_remote_hangup_and_ack_timeout.md @@ -0,0 +1,30 @@ +# Исправление завершения звонка и таймаутов ACK + +## Краткое описание + +Исправлена клиентская логика звонков: +- входящий экран теперь должен закрываться сразу при `remote_hangup`; +- после нажатия `Ответить` добавлен таймаут ожидания стадии `connecting`, чтобы окно не висело бесконечно; +- исходящий таймаут ожидания ACK больше не обрывает звонок слишком рано, если invite уже был доставлен. +- в локальный app log клиента добавлен точный timeline по этапам звонка: invite, выбор remoteSessionId, accept/offer/answer, ICE, смены `RTCPeerConnection` и финализация. +- добавлена явная диагностика `SESSION_NOT_FOUND` для звонковых сигналов: отдельный timeline-этап в клиенте и отдельный серверный warn-лог. + +## Что проверять + +- Если исходящая сторона завершила звонок, входящее окно у второй стороны закрывается сразу. +- Если принять входящий звонок, а соединение/offer не приходит, экран не висит бесконечно и сам завершается по таймауту. +- Если invite был доставлен, исходящий звонок не падает через 10 секунд раньше времени только из-за медленного ACK. +- В app log по звонку видна последовательность этапов с локальными `+N ms`, по которой можно понять, где именно образуется задержка или гонка. +- Если сигнал звонка не дошёл до целевой сессии, это явно видно и в клиенте, и в серверном логе. + +## Ожидаемый результат + +- Нет бесконечно висящего окна `Соединяем…` на принимающей стороне. +- В логах вместо преждевременного `no_ack_10s` для уже доставленного invite появляется более поздний таймаут. +- При `remote_hangup` звонок визуально завершается сразу. +- По каждому проблемному звонку есть локальный timeline и тот же краткий timeline попадает в `CallDeliveryReport`. +- В серверных логах есть строка `CALL_SIGNAL_SESSION_NOT_FOUND ...` с `callId`, `targetSessionId` и количеством активных сессий адресата. + +## Статус + +`pending` diff --git a/docs/deploy/README.md b/docs/deploy/README.md index 4ee7859..cf6d69d 100644 --- a/docs/deploy/README.md +++ b/docs/deploy/README.md @@ -19,11 +19,11 @@ - SSH: `player@shineup.me` - Домен: `shineup.me` - IP: `185.229.109.118` -- Main test: +- Second production: - SSH: `player@193.8.215.70` - Домен: `t.shineup.me` - IP: `193.8.215.70` -- Reserve test: +- Reserve test (temporarily down): - SSH: `player@93.170.12.154` - Домен: `test.shineup.me` - IP: `93.170.12.154` @@ -45,14 +45,14 @@ ## Политика подтверждений -- `shineup.me` — production. -- Любые изменения на `shineup.me`, включая deploy сервера, deploy UI, конфиги, перезапуски и миграции, делать только после отдельного явного подтверждения пользователя. -- Если пользователь пишет просто `задеплой` без уточнения, по умолчанию это означает deploy на `t.shineup.me`. +- `shineup.me` и `t.shineup.me` считать production-контурами. +- Любые изменения на production-контурах, включая deploy сервера, deploy UI, конфиги, перезапуски и миграции, делать только после отдельного явного подтверждения пользователя. +- `test.shineup.me` считать резервным тестовым хостом, который сейчас временно не работает. -## Main test deploy (`t.shineup.me`) +## Second production deploy (`t.shineup.me`) -- Это основной сервер для тестов. -- `deployServer` и `deployUI` по умолчанию направлены именно сюда. +- Это второй production-сервер SHiNE. +- Исторические задачи `deployServer`, `deployUI`, `deployServerTest2`, `deployUITest2` по-прежнему могут указывать сюда. - Серверный deploy не запускает JUnit/IT-тесты на удалённом сервере. - `deployServer` / `deployServerTest2` делают: - сборку fat-jar локально; @@ -66,6 +66,7 @@ ## Reserve test deploy (`test.shineup.me`) - `test.shineup.me` считается резервным тестовым сервером. +- Сейчас он помечен как временно неработающий. - Его настройки и адрес не менять без отдельной задачи. - Задачи `deployServerTest` и `deployUITest` считаются резервными и требуют отдельной причины. diff --git a/docs/deploy/servers/193.8.215.70_test2_main.md b/docs/deploy/servers/193.8.215.70_test2_main.md index 1321593..242f98c 100644 --- a/docs/deploy/servers/193.8.215.70_test2_main.md +++ b/docs/deploy/servers/193.8.215.70_test2_main.md @@ -1,4 +1,4 @@ -# Сервер `193.8.215.70` — основной test (`t.shineup.me`) +# Сервер `193.8.215.70` — второй production (`t.shineup.me`) - Пользователь: `player` - Домен: `t.shineup.me` @@ -18,9 +18,9 @@ ## Статус -- Это основной сервер для тестов SHiNE. -- Default deploy по умолчанию должен идти сюда. -- Источник данных для тестовой БД: production `shineup.me`. +- Это второй production-сервер SHiNE. +- Исторические имена deploy-задач могут по-прежнему ссылаться на него как на `test2`. +- В документации и в списке окружений считать его production-контуром. ## Caddy diff --git a/docs/deploy/servers/93.170.12.154_rapsberry.md b/docs/deploy/servers/93.170.12.154_rapsberry.md index 7c79cd1..370281d 100644 --- a/docs/deploy/servers/93.170.12.154_rapsberry.md +++ b/docs/deploy/servers/93.170.12.154_rapsberry.md @@ -19,6 +19,7 @@ ## Статус - Резервный тестовый сервер для SHiNE. +- Сейчас помечен как временно неработающий. - Источник данных для тестовой БД: production `shineup.me`. - Пока не использовать для обычного deploy. - Основной прод-сервер: `shineup.me` (`185.229.109.118`). diff --git a/shine-UI/js/services/call-service.js b/shine-UI/js/services/call-service.js index 723fa3d..2bd8e71 100644 --- a/shine-UI/js/services/call-service.js +++ b/shine-UI/js/services/call-service.js @@ -1,4 +1,4 @@ -import { addSignedMessageToChat, authService, authorizeSession, state } from '../state.js'; +import { addAppLogEntry, addSignedMessageToChat, authService, authorizeSession, state } from '../state.js'; import { buildDmCallTechBlock } from './dm-tech-blocks.js'; const TYPES = { @@ -28,11 +28,97 @@ const DEFAULT_ICE_SERVERS = Object.freeze([ { urls: 'stun:stun.l.google.com:19302' }, ]); const CALL_SUMMARY_MIN_TOTAL_MS = 5000; +const OUTGOING_NO_ACK_TIMEOUT_MS = 10_000; +const OUTGOING_DELIVERED_NO_ACK_TIMEOUT_MS = 25_000; +const INCOMING_CONNECT_TIMEOUT_MS = 20_000; +const MAX_TIMELINE_ENTRIES = 64; function nowMs() { return Date.now(); } +function sanitizeTimelineText(value) { + return String(value || '') + .replace(/\s+/g, ' ') + .replace(/[,]/g, ';') + .trim(); +} + +function getSignalTypeName(type) { + const normalized = Number(type); + if (normalized === TYPES.INVITE) return 'invite'; + if (normalized === TYPES.RINGING) return 'ringing'; + if (normalized === TYPES.ACCEPT) return 'accept'; + if (normalized === TYPES.DECLINE_BUSY) return 'decline_busy'; + if (normalized === TYPES.TIMEOUT) return 'timeout'; + if (normalized === TYPES.HANGUP) return 'hangup'; + if (normalized === TYPES.OFFER) return 'offer'; + if (normalized === TYPES.ANSWER) return 'answer'; + if (normalized === TYPES.ICE) return 'ice'; + return `type_${String(type || '')}`; +} + +function ensureCallTimeline(call) { + if (!call) return; + if (!Array.isArray(call.timelineEvents)) call.timelineEvents = []; + if (!Number.isFinite(call.timelineSeq)) call.timelineSeq = 0; + if (!Number.isFinite(call.timelineBaseMs) || call.timelineBaseMs <= 0) { + call.timelineBaseMs = Number(call.startedAtMs || nowMs()); + } +} + +function recordCallTimeline(call, stage, details = '', level = 'info') { + if (!call) return; + ensureCallTimeline(call); + const ts = nowMs(); + const deltaMs = Math.max(0, ts - Number(call.timelineBaseMs || ts)); + const cleanStage = sanitizeTimelineText(stage) || 'unknown'; + const cleanDetails = sanitizeTimelineText(details); + call.timelineSeq += 1; + call.timelineEvents.push({ + seq: call.timelineSeq, + ts, + deltaMs, + stage: cleanStage, + details: cleanDetails, + }); + if (call.timelineEvents.length > MAX_TIMELINE_ENTRIES) { + call.timelineEvents.splice(0, call.timelineEvents.length - MAX_TIMELINE_ENTRIES); + } + addAppLogEntry({ + level, + source: 'call', + message: `[${call.callId || '?'}] +${deltaMs}ms ${cleanStage}`, + details: cleanDetails || buildCallFactsJson(call), + }); +} + +function buildTimelineSummary(call) { + const events = Array.isArray(call?.timelineEvents) ? call.timelineEvents : []; + if (!events.length) return ''; + return events + .map((entry) => { + const head = `+${Number(entry?.deltaMs || 0)}:${sanitizeTimelineText(entry?.stage || '')}`; + const tail = sanitizeTimelineText(entry?.details || ''); + return tail ? `${head}(${tail})` : head; + }) + .join('|') + .slice(0, 1800); +} + +function setRemoteSessionId(call, sessionId, reason = '') { + if (!call) return; + const next = String(sessionId || '').trim(); + if (!next) return; + const prev = String(call.remoteSessionId || '').trim(); + if (prev === next) { + recordCallTimeline(call, 'remote_session_confirmed', `session=${next}; reason=${reason || 'same'}`); + return; + } + call.remoteSessionId = next; + recordCallTimeline(call, 'remote_session_selected', `from=${prev || '-'}; to=${next}; reason=${reason || 'unknown'}`); +} + function resolveCallPreflightTimeoutMs() { const configured = Number(state?.entrySettings?.callPreflightTimeoutMs || 6000); return Math.max(1000, Math.min(20000, Number.isFinite(configured) ? configured : 6000)); @@ -112,6 +198,16 @@ function isInviteUndelivered(call) { return (wsDelivered + pushDelivered) <= 0; } +function getInviteDeliveredCount(call) { + const wsDelivered = Number(call?.inviteDelivery?.deliveredWsSessions || 0); + const pushDelivered = Number( + call?.inviteDelivery?.deliveredWebPushSessions + || call?.inviteDelivery?.deliveredFcmSessions + || 0 + ); + return wsDelivered + pushDelivered; +} + function buildOutgoingCallSummaryText(call, summaryCode) { if (!call || call.direction !== 'out') return ''; if (summaryCode === 'completed') { @@ -492,6 +588,7 @@ function setStatus(call, statusText, phase = '') { else if (call.phase === 'incoming') startTone('incoming'); else stopTone(); + recordCallTimeline(call, 'status', `phase=${call.phase || ''}; text=${call.statusText || ''}`); void emitDebug(call, 'info', `call_status: ${call.statusText}`, `callId=${call.callId}`); notifyCallState(); } @@ -531,6 +628,7 @@ function buildCallFactsJson(call, extra = {}) { pcSignalingState: pc?.signalingState || '', hasLocalStream: Boolean(call?.localStream), localAudioTracksCount: call?.localStream?.getAudioTracks?.()?.length || 0, + timeline: buildTimelineSummary(call), ...extra, }; try { @@ -560,6 +658,7 @@ function buildCallFactsLine(call, extra = {}) { pcSignalingState: pc?.signalingState || '', hasLocalStream: Boolean(call?.localStream), localAudioTracksCount: call?.localStream?.getAudioTracks?.()?.length || 0, + timeline: buildTimelineSummary(call), ...extra, }; return Object.entries(facts) @@ -634,6 +733,7 @@ async function sendCallDeliveryReport(call, eventType, eventCode, reason = '', e reason: String(reason || '').trim(), reportedAtMs: nowMs(), reportedAtIso: toIsoTs(nowMs()), + timelineEntriesCount: Array.isArray(call?.timelineEvents) ? call.timelineEvents.length : 0, ...diagnostics, ...extraFacts, }); @@ -648,10 +748,49 @@ function cleanupTimers(call) { if (call.timers?.ack10s) clearTimeout(call.timers.ack10s); if (call.timers?.total35s) clearTimeout(call.timers.total35s); if (call.timers?.incoming20s) clearTimeout(call.timers.incoming20s); + if (call.timers?.incomingConnect20s) clearTimeout(call.timers.incomingConnect20s); if (call.timers?.transportProbe) clearInterval(call.timers.transportProbe); call.timers.transportProbe = null; } +function scheduleOutgoingAckTimeout(call) { + if (!call?.timers) return; + if (call.timers.ack10s) { + clearTimeout(call.timers.ack10s); + call.timers.ack10s = null; + } + const deliveredCount = getInviteDeliveredCount(call); + const timeoutMs = deliveredCount > 0 + ? OUTGOING_DELIVERED_NO_ACK_TIMEOUT_MS + : OUTGOING_NO_ACK_TIMEOUT_MS; + const debugReason = deliveredCount > 0 ? 'no_ack_after_delivery_25s' : 'no_ack_10s'; + recordCallTimeline(call, 'ack_timeout_scheduled', `timeoutMs=${timeoutMs}; delivered=${deliveredCount}; reason=${debugReason}`); + call.timers.ack10s = setTimeout(() => { + if (!calls.has(call.callId)) return; + if (call.phase === 'searching' || call.phase === 'ringing') { + recordCallTimeline(call, 'ack_timeout_fired', `phase=${call.phase || ''}; reason=${debugReason}`, 'warn'); + void finalizeCall(call, { localReasonCode: 'no_answer', debugReason }); + } + }, timeoutMs); +} + +function scheduleIncomingConnectTimeout(call) { + if (!call?.timers) return; + if (call.timers.incomingConnect20s) { + clearTimeout(call.timers.incomingConnect20s); + } + recordCallTimeline(call, 'incoming_connect_timeout_scheduled', `timeoutMs=${INCOMING_CONNECT_TIMEOUT_MS}`); + call.timers.incomingConnect20s = setTimeout(() => { + if (!calls.has(call.callId)) return; + if (call.phase !== 'connecting') return; + recordCallTimeline(call, 'incoming_connect_timeout_fired', `phase=${call.phase || ''}`, 'warn'); + void finalizeCall(call, { + localReasonCode: 'no_answer', + debugReason: 'incoming_connect_timeout_20s', + }); + }, INCOMING_CONNECT_TIMEOUT_MS); +} + async function flushPendingIceCandidates(call) { if (!call?.pc) return; const pending = Array.isArray(call.pendingRemoteIceCandidates) ? call.pendingRemoteIceCandidates : []; @@ -831,6 +970,7 @@ function startReconnectFlow(call, reason = 'disconnected') { call.reconnectInProgress = true; call.reconnectAttempts = 0; + recordCallTimeline(call, 'reconnect_start', `reason=${reason}`); setStatus(call, 'Связь прервалась. Переподключаем…', 'reconnecting'); void emitDebug(call, 'warn', 'peer_connection_reconnect_start', `reason=${reason}`); @@ -853,6 +993,7 @@ function startReconnectFlow(call, reason = 'disconnected') { } call.reconnectAttempts += 1; + recordCallTimeline(call, 'reconnect_attempt', `attempt=${call.reconnectAttempts}`); try { const offer = await call.pc.createOffer({ iceRestart: true }); await call.pc.setLocalDescription(offer); @@ -888,10 +1029,19 @@ async function finalizeCall(call, { suppressSummary = false, } = {}) { if (!call) return; + recordCallTimeline( + call, + 'finalize_begin', + `reason=${localReasonCode || ''}; debug=${debugReason || ''}; phase=${call.phase || ''}`, + String(localReasonCode || '') === 'completed' ? 'info' : 'warn', + ); const diagnosticsBeforeClose = getCallDiagnosticsContext(call); cleanupTimers(call); stopReconnectFlow(call); stopTone(); + if (String(debugReason || '') === 'remote_hangup' && call.direction === 'in') { + dismissCallUiLocally(call); + } const shouldNotifyRemoteFailure = !suppressRemoteSignal @@ -955,6 +1105,7 @@ async function finalizeCall(call, { if (String(localReasonCode || '') === 'busy') { call.statusText = 'Пользователь занят'; } + recordCallTimeline(call, 'finalize_end', `reason=${localReasonCode || ''}; status=${call.statusText || ''}`); notifyCallState(); const finalHoldMs = String(localReasonCode || '') === 'busy' ? 2600 : 0; @@ -990,6 +1141,7 @@ async function emitDebug(call, level, message, details = '') { async function sendSignal(call, type, data = '') { if (!call.remoteSessionId) return; + const signalName = getSignalTypeName(type); try { await authService.callSignalToSession({ toLogin: call.peerLogin, @@ -998,8 +1150,18 @@ async function sendSignal(call, type, data = '') { type, data, }); + recordCallTimeline(call, `signal_out_${signalName}`, `toSession=${call.remoteSessionId}; len=${String(data || '').length}`); await emitDebug(call, 'info', `signal_sent_${type}`, `len=${String(data || '').length}`); } catch (error) { + if (String(error?.code || '').toUpperCase() === 'SESSION_NOT_FOUND') { + recordCallTimeline( + call, + `signal_out_${signalName}_session_not_found`, + `toSession=${call.remoteSessionId}; op=${String(error?.op || '')}; status=${String(error?.status || '')}`, + 'warn', + ); + } + recordCallTimeline(call, `signal_out_${signalName}_failed`, `toSession=${call.remoteSessionId}; error=${toErrorText(error)}`, 'warn'); await emitDebug(call, 'error', `signal_send_failed_${type}`, toErrorText(error)); throw error; } @@ -1038,6 +1200,14 @@ async function ensurePeerConnection(call) { pc.onicecandidate = async (event) => { if (!event.candidate || !call.remoteSessionId) return; + call.localIceSentCount = Number(call.localIceSentCount || 0) + 1; + if (call.localIceSentCount <= 3) { + recordCallTimeline( + call, + 'ice_local_candidate', + `count=${call.localIceSentCount}; type=${event.candidate?.type || ''}; protocol=${event.candidate?.protocol || ''}`, + ); + } try { await sendSignal(call, TYPES.ICE, JSON.stringify(event.candidate)); } catch {} @@ -1045,8 +1215,18 @@ async function ensurePeerConnection(call) { pc.onconnectionstatechange = () => { const state = pc.connectionState; + recordCallTimeline( + call, + 'pc_connection_state', + `state=${state || ''}; ice=${pc.iceConnectionState || ''}; signal=${pc.signalingState || ''}`, + state === 'failed' ? 'warn' : 'info', + ); if (state === 'connected') { stopReconnectFlow(call); + if (call.timers?.incomingConnect20s) { + clearTimeout(call.timers.incomingConnect20s); + call.timers.incomingConnect20s = null; + } if (!call.connectedAtMs) { call.connectedAtMs = nowMs(); } @@ -1115,6 +1295,7 @@ async function ensurePeerConnection(call) { call.audioSenders = []; call.connectionRouteLabel = ''; call.connectionRouteDetails = ''; + recordCallTimeline(call, 'local_media_ready', `tracks=${stream.getTracks().length}`); stream.getTracks().forEach((track) => { track.enabled = track.kind === 'audio' ? !call.muted : true; const sender = pc.addTrack(track, stream); @@ -1124,11 +1305,13 @@ async function ensurePeerConnection(call) { }); } catch (e) { setStatus(call, `Нет доступа к микрофону: ${e?.message || 'unknown'}`, 'failed'); + recordCallTimeline(call, 'local_media_failed', toErrorText(e), 'warn'); await emitDebug(call, 'warn', 'microphone_access_failed', toErrorText(e)); throw e; } pc.ontrack = (evt) => { + recordCallTimeline(call, 'remote_track_received', `streams=${evt?.streams?.length || 0}`); const audio = new Audio(); audio.autoplay = true; audio.srcObject = evt.streams[0]; @@ -1148,6 +1331,7 @@ async function onAccept(call) { await emitDebug(call, 'warn', 'accept_duplicate_ignored', `phase=${call.phase || ''}`); return; } + recordCallTimeline(call, 'offer_start', `remoteSession=${call.remoteSessionId || ''}`); call.initialOfferInProgress = true; cleanupTimers(call); setStatus(call, 'Соединяем…', 'connecting'); @@ -1237,10 +1421,14 @@ async function handleIncomingInvitePayload(payload, { source = 'ws' } = {}) { pendingRemoteIceCandidates: [], initialOfferInProgress: false, initialOfferSent: false, + timelineEvents: [], + timelineSeq: 0, + timelineBaseMs: nowMs(), }; calls.set(callId, call); + recordCallTimeline(call, 'incoming_invite_created', `from=${fromLogin}; session=${fromSessionId}; source=${source}`); } else if (!call.remoteSessionId && fromSessionId) { - call.remoteSessionId = fromSessionId; + setRemoteSessionId(call, fromSessionId, 'incoming_invite_existing_call'); } activeCallId = callId; @@ -1396,10 +1584,14 @@ export async function startDebugConnectionAsInitiator({ runId, callId, peerLogin pendingRemoteIceCandidates: [], initialOfferInProgress: false, initialOfferSent: false, + timelineEvents: [], + timelineSeq: 0, + timelineBaseMs: nowMs(), }; calls.set(cleanCallId, call); activeCallId = cleanCallId; + recordCallTimeline(call, 'debug_initiator_created', `peer=${cleanPeerLogin}; session=${cleanPeerSessionId}`); notifyCallState(); await emitDebug(call, 'info', 'debug_start_initiator', `peerSessionId=${cleanPeerSessionId}`); try { @@ -1449,28 +1641,36 @@ export async function startOutgoingCall(peerLogin) { pendingRemoteIceCandidates: [], initialOfferInProgress: false, initialOfferSent: false, + timelineEvents: [], + timelineSeq: 0, + timelineBaseMs: nowMs(), }; calls.set(callId, call); activeCallId = callId; + recordCallTimeline(call, 'outgoing_created', `peer=${cleanPeer}`); setStatus(call, 'Ищем пользователя…', 'searching'); - call.timers.ack10s = setTimeout(() => { - if (!calls.has(callId)) return; - if (call.phase === 'searching') { - void finalizeCall(call, { localReasonCode: 'no_answer', debugReason: 'no_ack_10s' }); - } - }, 10000); - call.timers.total35s = setTimeout(() => { if (!calls.has(callId)) return; if (!call.connectedAtMs) { + recordCallTimeline(call, 'total_timeout_fired', 'total_timeout_35s', 'warn'); void finalizeCall(call, { localReasonCode: 'no_answer', debugReason: 'total_timeout_35s' }); } }, 35000); try { call.inviteDelivery = await authService.callInviteBroadcast({ toLogin: cleanPeer, callId, type: TYPES.INVITE }); + recordCallTimeline( + call, + 'invite_broadcast_ok', + `ws=${Number(call.inviteDelivery?.deliveredWsSessions || 0)}; push=${Number(call.inviteDelivery?.deliveredWebPushSessions || call.inviteDelivery?.deliveredFcmSessions || 0)}`, + ); + if (getInviteDeliveredCount(call) > 0 && call.phase === 'searching') { + setStatus(call, 'Вызываем…', 'ringing'); + } + scheduleOutgoingAckTimeout(call); } catch (error) { + recordCallTimeline(call, 'invite_broadcast_failed', toErrorText(error), 'warn'); const text = String(error?.message || '').toUpperCase(); const isNotAuth = text.includes('NOT_AUTHENTICATED'); if (isNotAuth) { @@ -1478,6 +1678,10 @@ export async function startOutgoingCall(peerLogin) { if (recovered) { try { call.inviteDelivery = await authService.callInviteBroadcast({ toLogin: cleanPeer, callId, type: TYPES.INVITE }); + if (getInviteDeliveredCount(call) > 0 && call.phase === 'searching') { + setStatus(call, 'Вызываем…', 'ringing'); + } + scheduleOutgoingAckTimeout(call); return; } catch {} } @@ -1496,9 +1700,11 @@ export async function handleIncomingCallInvite(evt) { export async function acceptIncomingCall() { const call = getActiveCall(); if (!call || call.direction !== 'in' || call.phase !== 'incoming') return; + recordCallTimeline(call, 'incoming_accept_clicked', `session=${call.remoteSessionId || ''}`); call.phase = 'connecting'; setStatus(call, 'Соединяем…', 'connecting'); cleanupTimers(call); + scheduleIncomingConnectTimeout(call); await sendSignal(call, TYPES.ACCEPT, 'accept'); } @@ -1530,12 +1736,15 @@ export async function handleIncomingCallSignal(evt) { const call = getCall(callId); if (!call) return; + const signalName = getSignalTypeName(type); + recordCallTimeline(call, `signal_in_${signalName}`, `from=${fromSessionId || '-'}; len=${data.length}`); if (call.direction === 'out') { if (type === TYPES.RINGING) { if (!call.remoteSessionId && fromSessionId) { - call.remoteSessionId = fromSessionId; + setRemoteSessionId(call, fromSessionId, 'ringing'); } if (call.remoteSessionId && fromSessionId && call.remoteSessionId !== fromSessionId) { + recordCallTimeline(call, 'signal_in_ringing_ignored', `selected=${call.remoteSessionId}; from=${fromSessionId}`); await emitDebug( call, 'info', @@ -1547,8 +1756,9 @@ export async function handleIncomingCallSignal(evt) { } else if (type === TYPES.ACCEPT) { if (fromSessionId) { if (!call.remoteSessionId || !call.initialOfferSent) { - call.remoteSessionId = fromSessionId; + setRemoteSessionId(call, fromSessionId, 'accept_before_offer_lock'); } else if (call.remoteSessionId !== fromSessionId) { + recordCallTimeline(call, 'signal_in_accept_ignored', `selected=${call.remoteSessionId}; from=${fromSessionId}`, 'warn'); await emitDebug( call, 'warn', @@ -1573,6 +1783,7 @@ export async function handleIncomingCallSignal(evt) { && (type === TYPES.DECLINE_BUSY || type === TYPES.TIMEOUT || type === TYPES.HANGUP); if (call.remoteSessionId && fromSessionId && call.remoteSessionId !== fromSessionId) { if (terminalSignalFromAnotherSession && !remoteSessionLocked) { + recordCallTimeline(call, 'terminal_signal_before_lock_allowed', `type=${signalName}; selected=${call.remoteSessionId}; from=${fromSessionId}`); await emitDebug( call, 'info', @@ -1580,6 +1791,7 @@ export async function handleIncomingCallSignal(evt) { `type=${type}; selected=${call.remoteSessionId}; from=${fromSessionId}`, ); } else { + recordCallTimeline(call, 'signal_in_ignored_non_selected_session', `type=${signalName}; selected=${call.remoteSessionId}; from=${fromSessionId}`); await emitDebug( call, 'info', @@ -1590,11 +1802,11 @@ export async function handleIncomingCallSignal(evt) { } } if (!call.remoteSessionId && fromSessionId) { - call.remoteSessionId = fromSessionId; + setRemoteSessionId(call, fromSessionId, `first_${signalName}`); } } } else if (!call.remoteSessionId) { - call.remoteSessionId = fromSessionId; + setRemoteSessionId(call, fromSessionId, `incoming_${signalName}`); } if (type === TYPES.RINGING) { @@ -1640,6 +1852,7 @@ export async function handleIncomingCallSignal(evt) { if (type === TYPES.OFFER) { try { + recordCallTimeline(call, 'offer_processing_start', `from=${fromSessionId || '-'}`); const pc = await ensurePeerConnection(call); await pc.setRemoteDescription(new RTCSessionDescription(JSON.parse(data))); await flushPendingIceCandidates(call); @@ -1677,6 +1890,7 @@ export async function handleIncomingCallSignal(evt) { } await pc.setRemoteDescription(new RTCSessionDescription(JSON.parse(data))); await flushPendingIceCandidates(call); + recordCallTimeline(call, 'answer_applied', `from=${fromSessionId || '-'}`); setStatus(call, 'Соединяем…', 'connecting'); await emitDebug(call, 'info', 'answer_processed', 'remote description set'); } catch (error) { @@ -1689,9 +1903,13 @@ export async function handleIncomingCallSignal(evt) { if (type === TYPES.ICE) { try { const candidate = JSON.parse(data); + call.remoteIceReceivedCount = Number(call.remoteIceReceivedCount || 0) + 1; if (!call.pc) { if (!Array.isArray(call.pendingRemoteIceCandidates)) call.pendingRemoteIceCandidates = []; call.pendingRemoteIceCandidates.push(candidate); + if (call.remoteIceReceivedCount <= 3) { + recordCallTimeline(call, 'ice_remote_queued_no_pc', `count=${call.remoteIceReceivedCount}; queue=${call.pendingRemoteIceCandidates.length}`); + } await emitDebug(call, 'info', 'ice_queued_before_pc', `queue=${call.pendingRemoteIceCandidates.length}`); return; } @@ -1699,10 +1917,16 @@ export async function handleIncomingCallSignal(evt) { if (!pc.remoteDescription) { if (!Array.isArray(call.pendingRemoteIceCandidates)) call.pendingRemoteIceCandidates = []; call.pendingRemoteIceCandidates.push(candidate); + if (call.remoteIceReceivedCount <= 3) { + recordCallTimeline(call, 'ice_remote_queued_no_remote_description', `count=${call.remoteIceReceivedCount}; queue=${call.pendingRemoteIceCandidates.length}`); + } await emitDebug(call, 'info', 'ice_queued_before_remote_description', `queue=${call.pendingRemoteIceCandidates.length}`); return; } await pc.addIceCandidate(new RTCIceCandidate(candidate)); + if (call.remoteIceReceivedCount <= 3) { + recordCallTimeline(call, 'ice_remote_applied', `count=${call.remoteIceReceivedCount}`); + } await emitDebug(call, 'info', 'ice_processed', 'candidate added'); } catch (error) { await emitDebug(call, 'error', 'ice_process_failed', toErrorText(error)); @@ -1714,6 +1938,7 @@ export async function hangupActiveCall() { if (!activeCallId) return; const call = getCall(activeCallId); dismissCallUiLocally(call); + recordCallTimeline(call, 'hangup_clicked', `connected=${Boolean(call?.connectedAtMs)}`); await finalizeCall(call, { localReasonCode: call?.connectedAtMs ? 'completed' : 'no_answer', debugReason: 'hangup_by_user', @@ -1740,6 +1965,7 @@ export async function handleStopCallPush(payload = {}) { await emitDebug(call, 'info', 'stop_call_push_ignored_for_origin_session', reason); return; } + recordCallTimeline(call, 'stop_call_push', `fromSession=${fromSessionId || '-'}; reason=${reason}`); await finalizeCall(call, { localReasonCode: call.connectedAtMs ? 'completed' : 'no_answer', debugReason: `stop_call_push:${reason}`,