Анализ логов Softphone.Pro: односторонняя слышимость, не совершается звонок, не поступают входящие звонки

В процессе работы с софтфоном пользователи могут столкнуться с различными ситуациями, например:

Как правило такие ситуации возникают в самый неподходящий момент и требуют оперативного анализа и поиска причин. Зачастую для решения подобных ситуаций требуется привлечь специалистов смежных подразделений, поддержку оператора связи и т.д. Данным специалистам требуется передать исчерпывающую информацию по ситуации с примерами её возникновения.

В этой статье описано, как получить и проанализировать информацию по ситуации, используя логи Softphone.Pro.

Как и где найти лог файлы софтфона

Ознакомьтесь с данной статьёй, чтобы найти информацию о том как включить логирование и выбрать уровень логирования. Далее в статье будем считать, что включен уровень логирования Debug.

Чтобы открыть папку с логами, откройте настройки приложения, и на вкладке Основные в разделе Данные приложения нажмите кнопку Открыть:

Открыть папку с логами приложения

Если вы изменили путь для сохранения логов, откройте папку, указанную в параметре Путь к файлу журнала или откройте файл журнала кнопкой Открыть лог файл справа от поля Путь к файлу журнала.

В открывшейся папке найдите файлы логов (файлы с SoftphoneProLogFile в названии) и откройте их в любом удобном вам текстовом редакторе.

Для примеров далее будем использовать редактор Notepad++.

Поиск нужных строк в Notepad++

Notepad++ обладает широкими возможностями по поиску, в том числе по регулярным выражениям. Чтобы включить поиск по регулярным выражениям, откройте лог файл SoftphoneProLogFile.txt в Notepad++, откройте меню Поиск - Найти (или нажмите Ctrl-F), и в разделе Режим поиска выберите пункт Регулярные выражения:

Включить поиск по регулярным выражениям

Далее в примерах будем приводить регулярные выражения, которые позволят найти нужные строки в лог файле.

Часто используемые аббревиатуры и действия в логе

Часто встречающиеся строки в логе

В логе вы можете увидеть, что одни и те же сокращения повторяются множество раз. Опишем наиболее полезные для диагностики поведения приложения строки.

Строка в логе	Описание
RX	Полученные с АТС данные (например, событие INVITE при входящем звонке, ответ SIP/2.0 200 OK на событие BYE завершения звонка, полученные голосовые пакеты в статистике по звонку). Пример: `RX 563 bytes Response msg 100/INVITE`
TX	Отправленные на АТС данные (например, событие INVITE при исходящем звонке, ответ SIP/2.0 180 Ringing на событие INVITE входящего звонка, отправленные голосовые пакеты в статистике по звонку). Пример: `TX 319 bytes Response msg 200/BYE`
Making call with acc {ACCOUNT_ID} to <{NUMBER} @{SIP_SERVER}>	Начало исходящего звонка. В строке лога отображается ID SIP учётной записи {ACCOUNT_ID}, через которую начат звонок (порядковый номер с 0), номер клиента {NUMBER}, на который совершается звонок, и SIP сервер АТС {SIP_SERVER}, на который отправляется запрос. Пример: `Making call with acc #0 to <sip:79991234567@sip.example.com>`
TX ... Request	Отправленный на АТС запрос (например, запрос REGISTER для регистрации SIP учётной записи на АТС или запрос INVITE для совершения исходящего звонка). Пример: `TX 986 bytes Request msg INVITE`
RX ... Request	Полученный с АТС запрос (например, запрос INVITE для входящего звонка или запрос BYE для завершения звонка). Пример: `RX 455 bytes Request msg BYE`
TX ... Response	Отправленный на АТС ответ на запрос (например, ответ SIP/2.0 200 OK для принятия входящего звонка). Пример: `TX 872 bytes Response msg 200/INVITE`
RX ... Response	Полученный с АТС ответ на запрос софтфона (например, ответ SIP/2.0 200 OK в ответ на запрос REGISTER). Пример: `RX 883 bytes Response msg 200/INVITE`
Call-ID: {CALL_ID}	Уникальный идентификатор звонка. Обычно сохраняется неизменным на протяжении всего звонка и позволяет отследить в логе все события, отправленные и полученные по звонку. Пример: `Call-ID: e0024d12211e48b0bc6a813d50d0b876`
Statistics for ...	Статистика по звонку. Подробно значимые параметры описаны далее в статье. Пример: см. пример 1, пример 2.
Incoming call notification window appeared	Начался входящий звонок и появилось окно-уведомление по центру экрана.
Small incoming call notification window appeared	Начался входящий звонок и появилось окно-уведомление в правом нижнем углу экрана.
User clicked Answer button	Оператор нажал кнопку Ответить в окне входящего звонка или в окне Активные звонки.
User clicked Hangup button	Оператор нажал кнопку Завершить звонок в окне входящего звонка или в окне Активные звонки.

На что обратить внимание при анализе статистики по звонку

Опишем поля диагностической информации (статистики) по звонку, на которые следует обратить внимание при анализе ситуации.

Раздел статистики	Строка в логе	Описание
RX	Total number of packets	Количество полученных с АТС голосовых пакетов.
	Total number of discarded packets	Количество отклоненных голосовых пакетов из полученных с АТС.
	Total number of packets lost	Количество потерянных голосовых пакетов из полученных с АТС.
TX	Total number of packets	Количество отправленных на АТС голосовых пакетов.
	Total number of discarded packets	Количество отклоненных голосовых пакетов из отправленных на АТС.
	Total number of packets lost	Количество потерянных голосовых пакетов из отправленных на АТС.
Jitter statistic	Average delay	Среднее значение задержки при передаче голосовых пакетов (в миллисекундах).
	Maximum delay	Максимальное значение задержки при передаче голосовых пакетов (в миллисекундах).
	Number of lost frames	Количество потерянных голосовых фреймов.
	Number of discarded frames	Количество отклоненных голосовых фреймов.

Примеры успешных звонков в логах софтфона

Для того чтобы найти звонок в логах приложения и понять, как он был обработан, вам нужно знать:

время начала звонка;
время окончания звонка;
номер А (номер с которого совершён звонок);
номер Б (номер, на который совершён звонок).

Зная эти данные, вы можете найти звонок в логах приложения и понять, как он был обработан.

Приведём примеры успешно совершённых звонков, чтобы наглядно показать, какие строки и события стоит искать в логах. Подробно на событиях и ответах SIP останавливаться не будем, ознакомиться с подробным описанием можно в RFC 3261. Также в строках заменили служебные данные на [...] для лучшей читаемости примеров.

Как найти в логах исходящий звонок

Начало исходящего звонка из софтфона сопровождается строкой в логе вида Making call with acc#0 to <sip:79991234567@sip.example.com>. Найти её в Notepad++ вы можете по регулярному выражению Making call with.*to - пример найденной строки:

[2025-02-19 17:08:27.032 +05:00] [...] !Making call with acc #0 to <sip:79991234567@sip.example.com>

Софтфон отправляет на АТС событие INVITE для того, чтобы начать звонок. В логе это сопровождается строкой, найти которую в Notepad++ вы можете по регулярному выражению TX.*bytes Request msg INVITE, за строкой следует дамп события:

[2025-02-19 17:08:27.043 +05:00] [...] TX 986 bytes Request msg INVITE/cseq=12879 (tdta1E62D12C) to UDP sip.example.com:5060:
INVITE sip:79991234567@sip.example.com SIP/2.0
Via: SIP/2.0/UDP 192.168.0.141:53457;rport;branch=z9hG4bKPjaac6cbf085e343c98a45c98888a582b1
Max-Forwards: 70
From: "46" <sip:46@sip.example.com>;tag=86bbcc03704a4c08abffe6421c2e13d9
To: <sip:79991234567@sip.example.com>
Contact: "46" <sip:46@192.168.0.141:53457;ob>
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 12879 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: SoftphonePro 5.10.0.0
Content-Type: application/sdp
Content-Length:   344

Вы можете увидеть несколько запросов INVITE в логе, например если АТС требует дополнительной авторизации. Если запрос обработан успешно, АТС отправляет в ответ на событие INVITE ответы SIP/2.0 100 Trying и SIP/2.0 180 Ringing, что говорит о том что начался дозвон до указанного номера. В логе это сопровождается строками, найти которые в Notepad++ вы можете по регулярному выражению RX.*bytes Response msg - пример найденных строк с дампами событий:

[2025-02-19 17:08:27.046 +05:00] [...] RX 563 bytes Response msg 100/INVITE/cseq=12880 (rdata1A089814) from UDP sip.example.com:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.141:53457;branch=z9hG4bKPj254d35451f414654aab2a2e0d31bbe81;received=192.168.0.141;rport=53457
From: "46" <sip:46@sip.example.com>;tag=86bbcc03704a4c08abffe6421c2e13d9
To: <sip:79991234567@sip.example.com>
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 12880 INVITE
Server: Asterisk PBX 16.22.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:79991234567@sip.example.com:5060>
Content-Length: 0

...

[2025-02-19 17:08:30.783 +05:00] [...] RX 579 bytes Response msg 180/INVITE/cseq=12880 (rdata1A089814) from UDP sip.example.com:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.141:53457;branch=z9hG4bKPj254d35451f414654aab2a2e0d31bbe81;received=192.168.0.141;rport=53457
From: "46" <sip:46@sip.example.com>;tag=86bbcc03704a4c08abffe6421c2e13d9
To: <sip:79991234567@sip.example.com>;tag=as797f5cc4
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 12880 INVITE
Server: Asterisk PBX 16.22.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:79991234567@sip.example.com:5060>
Content-Length: 0

После того как вторая сторона успешно ответит на звонок, АТС отправит в софтфон ответ SIP/2.0 200 OK (найти ответ можно по регулярному выражению RX.*bytes Response msg 200/INVITE):

[2025-02-19 17:08:36.049 +05:00] [...] RX 883 bytes Response msg 200/INVITE/cseq=12880 (rdata1A089814) from UDP sip.example.com:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.141:53457;branch=z9hG4bKPj254d35451f414654aab2a2e0d31bbe81;received=192.168.0.141;rport=53457
From: "46" <sip:46@sip.example.com>;tag=86bbcc03704a4c08abffe6421c2e13d9
To: <sip:79991234567@sip.example.com>;tag=as797f5cc4
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 12880 INVITE
Server: Asterisk PBX 16.22.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:79991234567@sip.example.com:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 260

Софтфон подтверждает начало звонка отправкой ответа ACK. В логе это сопровождается строкой, найти которую в Notepad++ вы можете по регулярному выражению TX.*bytes Request msg ACK, за строкой следует дамп события:

[2025-02-19 17:08:36.147 +05:00] [...] TX 341 bytes Request msg ACK/cseq=18858 (tdta1C6310AC) to UDP sip.example.com:5060:
ACK sip:49@sip.example.com:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.141:59229;rport;branch=z9hG4bKPj62e6b035b0694d67947c391e0dba90ba
Max-Forwards: 70
From: "46" <sip:46@sip.example.com>;tag=a2b61c99043e4a688f9cbb499deaa612
To: <sip:79991234567@sip.example.com>;tag=as56c925c0
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 12880 ACK
Content-Length:  0

Звонок начался.

Если звонок завершен на другой стороне диалога, в софтфон поступает событие BYE с АТС, которое указывает на то что нужно завершить звонок (найти его можно по регулярному выражению RX.*bytes Request msg BYE):

[2025-02-19 17:08:56.630 +05:00] [...] RX 594 bytes Request msg BYE/cseq=102 (rdata1A089814) from UDP sip.example.com:5060:
BYE sip:46@192.168.0.141:53457;ob SIP/2.0
Via: SIP/2.0/UDP sip.example.com:5060;branch=z9hG4bK349ee4d8;rport
Max-Forwards: 70
From: <sip:79991234567@sip.example.com>;tag=as797f5cc4
To: "46" <sip:46@sip.example.com>;tag=86bbcc03704a4c08abffe6421c2e13d9
Call-ID: e0024d12211e48b0bc6a813d50d0b876
CSeq: 102 BYE
User-Agent: Asterisk PBX 16.22.0
Proxy-Authorization: Digest username="46", realm="snowwhite", algorithm=MD5, uri="sip:sip.example.com", nonce="7fd922db", response="37fcb37c39b95a8b9959950504fcb71a"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

Софтфон отправляет в ответ SIP/2.0 200 OK и завершает звонок.

В лог записывается диагностическая информация по звонку после строки Media stream destroyed for call:

[2025-02-19 17:08:56.631 +05:00] [...] Media stream destroyed for call with id 5 - get statistic:

Statistics for 20 seconds of the last media stream (call 79991234567 in 2025-02-19 17:08:36 UUID e75b1270-9ae4-44e0-8431-3e1de292dcfb CALL-ID e0024d12211e48b0bc6a813d50d0b876):
RX:
Total number of packets: 1016
Total number of payload/bytes: 162560
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

TX:
Total number of packets: 1029
Total number of payload/bytes: 164640
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

Jitter Statistic:
Average delay, in ms: 58
Minimum delay, in ms: 20
Maximum delay, in ms: 80
Standard deviation of delay, in ms: 13
Average burst, in frames: 3
Number of lost frames: 0
Number of discarded frames: 0
Number of empty on GET events: 3

Jitter Settings:
Individual frame size, in bytes: 80
Minimum allowed prefetch, in frms: 1
Maximum allowed prefetch, in frms: 40

Jitter Status:
Current burst level, in frames: 4
Current prefetch value, in frames: 0
Current buffer size, in frames: 1

Codec name: PCMA/8000
Outgoing/incoming codec payload type: 8/8

Ненулевое значение в строке RX: Total number of packets: говорит о том, что с АТС были успешно получены голосовые пакеты. Ненулевое значение в строке TX: Total number of packets: говорит о том, что были успешно отправлены голосовые пакеты с софтфона на АТС.

Подробную информацию о данных метриках смотрите в таблице.

Как найти в логах входящий звонок

В начале входящего звонка софтфон получает с АТС событие INVITE. В логе это сопровождается строкой, найти которую в Notepad++ вы можете по регулярному выражению RX.*bytes Request msg INVITE, за строкой следует дамп события, полученного софтфоном с АТС. Например:

[2025-02-20 11:29:47.964 +05:00] [...] RX 851 bytes Request msg INVITE/cseq=102 (rdata18A96EF4) from UDP sip.example.com:5060:
INVITE sip:46@192.168.0.141:57753;ob SIP/2.0
Via: SIP/2.0/UDP sip.example.com:5060;branch=z9hG4bK125070e4
Max-Forwards: 70
From: "Sales" <sip:+79991234567@sip.example.com>;tag=as3609d76b
To: <sip:46@192.168.0.141:57753;ob>
Contact: <sip:+79991234567@sip.example.com:5060>
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 16.22.0
Date: Thu, 20 Feb 2025 06:29:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 262

Софтфон отправляет в ответ на INVITE сообщения SIP/2.0 100 Trying и SIP/2.0 180 Ringing. В логе это сопровождается строками, найти которые в Notepad++ вы можете по регулярному выражению TX.*bytes Response msg - пример найденных строк с дампами событий:

[2025-02-20 11:29:47.975 +05:00] [...] TX 291 bytes Response msg 100/INVITE/cseq=102 (tdta18AF36EC) to UDP sip.example.com:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP sip.example.com:5060;received=sip.example.com;branch=z9hG4bK125070e4
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
From: "Sales" <sip:+79991234567@sip.example.com>;tag=as3609d76b
To: 
CSeq: 102 INVITE
Content-Length:  0

...

[2025-02-20 11:29:47.975 +05:00] [...] TX 474 bytes Response msg 180/INVITE/cseq=102 (tdta18AF46F4) to UDP sip.example.com:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP sip.example.com:5060;received=sip.example.com;branch=z9hG4bK125070e4
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
From: "Sales" <sip:+79991234567@sip.example.com>;tag=as3609d76b
To: <sip:46@192.168.0.141;ob>;tag=425417b023da4d058fa5fd904ec0dde1
CSeq: 102 INVITE
Contact: "46" <sip:46@192.168.0.141:57753;ob>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

Софтфон показывает оператору окно начала входящего звонка, об этом говорят строки Incoming call notification window appeared (для окна по центру экрана) или Small incoming call notification window appeared (для окна в правом нижнем углу) в логе. Для звонка из примера Оператор увидел окно по центру экрана:

[2025-02-20 11:29:48.142 +05:00] [...] Incoming call notification window appeared

После того как Оператор ответил на звонок кликом по кнопке Ответить, в логе появляется строка вида User clicked Answer button, например:

[2025-02-20 11:29:49.786 +05:00] [...] Incoming window: User clicked Answer button

Софтфон отправляет на АТС ответ SIP/2.0 200 OK, который говорит о том что софтфон принял звонок (найти ответ можно по регулярному выражению TX.*bytes Response msg 200/INVITE):

[2025-02-20 11:29:49.788 +05:00] [...] TX 872 bytes Response msg 200/INVITE/cseq=102 (tdta1D511354) to UDP sip.example.com:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP sip.example.com:5060;received=sip.example.com;branch=z9hG4bK125070e4
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
From: "Sales" <sip:+7991234567@sip.example.com>;tag=as3609d76b
To: <sip:46@192.168.0.141;ob>;tag=425417b023da4d058fa5fd904ec0dde1
CSeq: 102 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: "46" <sip:46@192.168.0.141:57753;ob>
Supported: replaces, 100rel, timer, norefersub
Content-Type: application/sdp
Content-Length:   321

АТС подтверждает ответ на звонок запросом ACK (найти его можно по регулярному выражению RX.*bytes Request msg ACK):

[2025-02-20 11:29:49.789 +05:00] [...] RX 430 bytes Request msg ACK/cseq=102 (rdata0A25F0FC) from UDP sip.example.com:5060:
ACK sip:46@192.168.0.141:57753;ob SIP/2.0
Via: SIP/2.0/UDP sip.example.com:5060;branch=z9hG4bK326221be
Max-Forwards: 70
From: "Sales" <sip:+79991234567@sip.example.com>;tag=as3609d76b
To: <sip:46@192.168.0.141:57753;ob>;tag=425417b023da4d058fa5fd904ec0dde1
Contact: <sip:+79991234567@sip.example.com:5060>
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 16.22.0
Content-Length: 0

Звонок начался.

Если звонок завершён Оператором, который нажал на кнопку Завершить звонок, в логе появится строчка с текстом вида User clicked Hangup button, например:

[2025-02-20 11:32:51.091 +05:00] [...] Floating window: User clicked Hangup button

Софтфон отправляет на АТС запрос BYE для завершения звонка (найти его в логе можно по регулярному выражению TX.*bytes Request msg BYE):

[2025-02-20 11:32:51.093 +05:00] [...] TX 421 bytes Request msg BYE/cseq=24355 (tdta1D50B324) to UDP sip.example.com:5060:
BYE sip:+79991234567@sip.example.com:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.141:57753;rport;branch=z9hG4bKPj4c294bedd77f41198a56296a340f0de6
Max-Forwards: 70
From: <sip:46@192.168.0.141;ob>;tag=425417b023da4d058fa5fd904ec0dde1
To: "Sales" <sip:+79991234567@sip.example.com>;tag=as3609d76b
Call-ID: 71d507c61a4d08455681617574be07c4@sip.example.com:5060
CSeq: 24355 BYE
User-Agent: SoftphonePro 5.10.0.0
Content-Length:  0

Софтфон записывает в лог диагностическую статистику по звонку после строки Media stream destroyed for call, например:

[2025-02-20 11:32:51.093 +05:00] [...] Media stream destroyed for call with id 0 - get statistic:
 
Statistics for 182 seconds of the last media stream (call +79991234567 in 2025-02-20 11:29:49 UUID 72e6fe7d-1f18-4a54-b59b-63fa7f7ef3dc CALL-ID 71d507c61a4d08455681617574be07c4@sip.example.com:5060):
RX:
Total number of packets: 9056
Total number of payload/bytes: 1448960
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

TX:
Total number of packets: 9067
Total number of payload/bytes: 1450720
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

Jitter Statistic:
Average delay, in ms: 28
Minimum delay, in ms: 20
Maximum delay, in ms: 80
Standard deviation of delay, in ms: 12
Average burst, in frames: 2
Number of lost frames: 0
Number of discarded frames: 0
Number of empty on GET events: 13

Jitter Settings:
Individual frame size, in bytes: 80
Minimum allowed prefetch, in frms: 1
Maximum allowed prefetch, in frms: 40

Jitter Status:
Current burst level, in frames: 3
Current prefetch value, in frames: 0
Current buffer size, in frames: 0

Подробную информацию о данных метриках смотрите в таблице.

Диагностика неполадок по логам софтфона

Далее рассмотрим частые ситуации, с которыми могут столкнуться пользователи софтфона, и ответим для каждой на три вопроса:

Что произошло;
Что видно в логах;
Что делать для исправления ситуации.

Для краткости не будем приводить полные дампы SIP запросов и ответов.

Оператор не может ответить на входящий звонок

Что произошло: Оператор получает входящий звонок, нажимает на кнопку Ответить, но ничего не происходит – звонок не начинается. Звонок сбрасывается автоматически спустя определённое время.

Что видно в логах: в логах приложения можно увидеть, что софтфон отправляет на АТС ответы SIP/2.0 200 OK, но не получает подтверждение от АТС в виде сообщения ACK. Также в логе может быть сразу много ответов SIP/2.0 200 OK или событий INVITE, что говорит о том что АТС не получает ответы от софтфона. Так как АТС не получает события от софтфона, она отправляет событие CANCEL, завершая звонок.

Например, при поиске в Notepad++ по регулярному выражению TX .*bytes Response msg 200/INVITE в логе найдено множество однотипных ответов, которые софтфон отправляет на АТС:

[2025-02-20 11:29:49.788 +05:00] [SoftphonePro] [...] TX 872 bytes Response msg 200/INVITE/cseq=102 (tdta1D511354) to UDP sip.example.com:5060:
SIP/2.0 200 OK
...
[2025-02-20 11:29:50.788 +05:00] [SoftphonePro] [...] TX 872 bytes Response msg 200/INVITE/cseq=102 (tdta1D511354) to UDP sip.example.com:5060:
SIP/2.0 200 OK
...
[2025-02-20 11:29:51.788 +05:00] [SoftphonePro] [...] TX 872 bytes Response msg 200/INVITE/cseq=102 (tdta1D511354) to UDP sip.example.com:5060:
SIP/2.0 200 OK
...
[2025-02-20 11:29:52.788 +05:00] [SoftphonePro] [...] TX 872 bytes Response msg 200/INVITE/cseq=102 (tdta1D511354) to UDP sip.example.com:5060:
SIP/2.0 200 OK

При этом поиск по регулярному выражению RX.*bytes Request msg ACK не даёт результата.

Не получив ответ в течение определённого времени АТС отправляет в софтфон событие CANCEL, завершая звонок. Найти его в логе можно по регулярному выражению RX.*bytes Request msg CANCEL - пример:

[2025-02-20 11:29:54.132 +05:00] [...] RX 377 bytes Request msg CANCEL/cseq=102 (rdata1B307D4C) from UDP sip.example.com:5060:
CANCEL sip:46@192.168.0.141:1688;ob SIP/2.0
...

Что делать: свяжитесь с поддержкой вашей АТС или специалистами, которые занимаются её сопровождением, чтобы проверить, доходят ли запросы софтфона до АТС. Также ситуация может быть вызвана сетевыми неполадками на вашей инфраструктуре или АТС. Пожалуйста, обратитесь за помощью в их устранении к вашему системному администратору, провайдеру или поддержке АТС.

Софтфон не может зарегистрироваться на АТС с ошибкой 408

Что произошло: софтфон Оператора не регистрируется на АТС, в приложении видно ошибку 408. Оператор не может получать входящие звонки и совершать исходящие.

Что видно в логах: софтфон отправляет на АТС запросы REGISTER, но не получает на них ответ SIP/2.0 200 OK.

Поиск по регулярному выражению TX.*bytes Request msg REGISTER выдаёт множество запросов на регистрацию SIP учётной записи:

[2025-02-20 11:39:49.688 +05:00] [...] TX 768 bytes Request msg REGISTER/cseq=39382 (tdta3060592C) to UDP sip.example.com:5060:
REGISTER sip:sip.example.com SIP/2.0
...
[2025-02-20 11:39:54.688 +05:00] [...] TX 768 bytes Request msg REGISTER/cseq=39382 (tdta3060592C) to UDP sip.example.com:5060:
REGISTER sip:sip.example.com SIP/2.0
...
[2025-02-20 11:39:59.688 +05:00] [...] TX 768 bytes Request msg REGISTER/cseq=39382 (tdta3060592C) to UDP sip.example.com:5060:
REGISTER sip:sip.example.com SIP/2.0
...
[2025-02-20 11:40:04.688 +05:00] [...] TX 768 bytes Request msg REGISTER/cseq=39382 (tdta3060592C) to UDP sip.example.com:5060:
REGISTER sip:sip.example.com SIP/2.0

При этом поиск по выражению RX.*bytes Response msg 200/REGISTER не даёт результата.

Что делать: свяжитесь с поддержкой вашей АТС или специалистами, которые занимаются её сопровождением, чтобы проверить, поступают ли на АТС запросы REGISTER, и если да почему на них не отправляется ответ. Также ситуация может быть вызвана сетевыми неполадками на вашей инфраструктуре или АТС. Пожалуйста, обратитесь за помощью в их устранении к вашему системному администратору, провайдеру или поддержке АТС.

Оператор не может совершить исходящий звонок - нет гудков

Что произошло: Оператор пытается совершить звонок, звонок начинается но не слышно гудков. Звонок клиенту не совершается.

Что видно в логах: софтфон отправляет на АТС запросы INVITE, но не получает на них ответ.

Поиск по регулярному выражению TX.*bytes Request msg INVITE выдаёт множество запросов к АТС на совершение звонка:

[2025-02-19 17:08:27.043 +05:00] [...] TX 986 bytes Request msg INVITE/cseq=12879 (tdta1E62D12C) to UDP sip.example.com:5060:
INVITE sip:79991234567@sip.example.com SIP/2.0
...
[2025-02-19 17:08:28.043 +05:00] [...] TX 986 bytes Request msg INVITE/cseq=12879 (tdta1E62D12C) to UDP sip.example.com:5060:
INVITE sip:79991234567@sip.example.com SIP/2.0
...
[2025-02-19 17:08:29.043 +05:00] [...] TX 986 bytes Request msg INVITE/cseq=12879 (tdta1E62D12C) to UDP sip.example.com:5060:
INVITE sip:79991234567@sip.example.com SIP/2.0
...
[2025-02-19 17:08:30.043 +05:00] [...] TX 986 bytes Request msg INVITE/cseq=12879 (tdta1E62D12C) to UDP sip.example.com:5060:
INVITE sip:79991234567@sip.example.com SIP/2.0

При этом нет результатов поиска по выражению RX.*bytes Response msg с дампами событий SIP/2.0 100 Trying, SIP/2.0 180 Ringing и SIP/2.0 200 OK.

Что делать: свяжитесь с поддержкой вашей АТС или специалистами, которые занимаются её сопровождением, чтобы проверить, поступают ли на АТС запросы INVITE, и если да почему на них не отправляется ответ. Также ситуация может быть вызвана сетевыми неполадками на вашей инфраструктуре или АТС. Пожалуйста, обратитесь за помощью в их устранении к вашему системному администратору, провайдеру или поддержке АТС.

Оператор не слышит клиента или клиент не слышит Оператора (односторонняя слышимость)

Что произошло: Оператор совершает исходящий звонок или принимает входящий. Оператор слышит клиента, но клиент не слышит Оператора (или наоборот).

Что видно в логах: в статистике по звонку (можно найти в логе по выражению Statistics for.*seconds of the last media stream) в строке Total number of packets: стоит значение 0. Если значение равно нулю в строке в разделе RX, то голосовые пакеты с АТС не дошли до софтфона (Оператор не слышит клиента):

[2025-02-20 11:32:51.093 +05:00] [...] Media stream destroyed for call with id 0 - get statistic:

Statistics for 182 seconds of the last media stream (call +79991234567 in 2025-02-20 11:29:49 UUID 72e6fe7d-1f18-4a54-b59b-63fa7f7ef3dc CALL-ID 71d507c61a4d08455681617574be07c4@sip.example.com:5060):
RX:
Total number of packets: 0
Total number of payload/bytes: 0
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

TX:
Total number of packets: 9067
Total number of payload/bytes: 1450720
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 0
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0
...

Если значение равно нулю в строке Total number of packets: в разделе TX, то голосовые пакеты софтфона не дошли до АТС (клиент не слышит Оператора).

Что делать: если у вас используется какой-либо антивирус или файрвол, попробуйте отключить его и проверить работу приложения. Если ситуация исправится, вы можете добавить софтфон в исключения (пример для антивируса Касперского). В настройках SIP учётной записи попробуйте включить для сотрудника опцию Включить перезапись IP и сменить значение настройки Способ обхода брандмауэра (для сервиса Team используйте централизованную настройку). Также ситуация может быть вызвана сетевыми неполадками на вашей инфраструктуре или АТС. Пожалуйста, обратитесь за помощью в их устранении к вашему системному администратору, провайдеру или поддержке АТС.

Проблемы с качеством связи - звук Оператора и/или клиента прерывается ("квакает")

Что произошло: Оператор совершает исходящий звонок или принимает входящий. Оператор и клиент слышат друг друга, но звук прерывается ("квакает").

Что видно в логах: в статистике по звонку (можно найти в логе по выражению Statistics for.*seconds of the last media stream) в строке Total number of packets lost: ненулевое значение. Если значение больше нуля в строке в разделе RX, то голосовые пакеты с АТС теряются, не доходя до софтфона (Оператор плохо слышит клиента). Если значение больше нуля в строке в разделе TX, то голосовые пакеты софтфона теряются, не доходя до АТС (клиент плохо слышит Оператора).

Если потерь не наблюдается (в строках Total number of packets lost: значение 0), проверьте также значение метрик Number of lost frames и Number of discarded frames в разделе Jitter Statistic.

Если в данных полях значения больше нуля, значит наблюдаются неполадки с каналом связи (высокая загрузка, недостаточная пропускная способность).

Приведём пример звонка, у которого наблюдаются и потери пакетов, и неполадки с каналом связи:

[2025-02-20 11:42:51.093 +05:00] [...] Media stream destroyed for call with id 0 - get statistic:
  
Statistics for 213 seconds of the last media stream (call +79991234567 in 2025-02-20 11:29:49 UUID 72e6fe7d-1f18-4a54-b59b-63fa7f7ef3dc CALL-ID 71d507c61a4d08455681617574be07c4@sip.example.com:5060):
RX:
Total number of packets: 9056
Total number of payload/bytes: 1448960
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 123
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

TX:
Total number of packets: 9067
Total number of payload/bytes: 1450720
Total number of discarded packets: 0
Total number of out of order packets: 0
Total number of packets lost: 456
Total number of duplicates packets: 0
Burst/sequential packet lost detected: 0
Random packet lost detected: 0

Jitter Statistic:
Average delay, in ms: 28
Minimum delay, in ms: 20
Maximum delay, in ms: 80
Standard deviation of delay, in ms: 12
Average burst, in frames: 2
Number of lost frames: 567
Number of discarded frames: 702
Number of empty on GET events: 13

Jitter Settings:
Individual frame size, in bytes: 80
Minimum allowed prefetch, in frms: 1
Maximum allowed prefetch, in frms: 40

Jitter Status:
Current burst level, in frames: 3
Current prefetch value, in frames: 0
Current buffer size, in frames: 0

Что делать: если у вас используется какой-либо антивирус или файрвол, попробуйте отключить его и проверить работу приложения. Если ситуация исправится, вы можете добавить софтфон в исключения (пример для антивируса Касперского). Если вы используете подключение по Wi-Fi, попробуйте подключиться к сети по проводу. Также ситуация может быть вызвана сетевыми неполадками на вашей инфраструктуре или АТС или высокой загрузкой сети. Пожалуйста, обратитесь за помощью в их устранении к вашему системному администратору, провайдеру или поддержке АТС.

Список статей