Страница 1 из 1

OPTIONS с задержкой

Добавлено: 05 дек 2017, 19:52
itm
Приветствую господа, кончились мысли в голове, гугл и все чем можно воспользоваться, поэтому обращаюсь к вам:
Изначально проблема может показаться весьма проста(может она и реально пустяковая) весь лог засыпан, и уже несколько дней как все жалуются на обрывы связи:

Код: Выделить всё

[2017-12-05 16:30:36] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '101' is now UNREACHABLE!  Last qualify: 73
[2017-12-05 16:30:36] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '109' is now UNREACHABLE!  Last qualify: 74
[2017-12-05 16:30:36] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '106' is now UNREACHABLE!  Last qualify: 80
[2017-12-05 16:30:46] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '101' is now Reachable. (76ms / 2000ms)
[2017-12-05 16:30:46] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '109' is now Reachable. (73ms / 2000ms)
[2017-12-05 16:30:46] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '106' is now Reachable. (80ms / 2000ms)
Мониторинг дампов показал следующую проблему: Ответ на OPTIONS приходит с опазданием, что собственно и вызывает UNREACHABLE peer. Сам Астер находится в облаке, все клиенты за NAT, из этого можно сделать вывод, что тупо подвисает NAT, но я пробовал регистрировать софтфон с другого офиса другого провайдера интернет и ситуация та же!!!
Подобная картина может быть если бы, кто то пытался брутить PBX, но нет же iptables+fail2ban. Процессор ничего не грузит 1-10% обычная нагрузка! Подкиньте мыслишки куда думать. Debug с указанной проблемой ниже. Спасибо заранее.

Код: Выделить всё

Reliably Transmitting (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
Retransmitting #1 (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
Retransmitting #2 (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
Retransmitting #3 (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
Retransmitting #4 (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2017-12-05 16:05:35] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '102' is now UNREACHABLE!  Last qualify: 180
Really destroying SIP dialog '22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060' Method: OPTIONS

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>;tag=776298603
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>;tag=776298603
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>;tag=776298603
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>;tag=776298603
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK35acbfd3;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as39e65f40
To: <sip:102@192.168.0.96:5062>;tag=776298603
Call-ID: 22cfd93a45fe29e166adf011367b7aca@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---

Reliably Transmitting (NAT) to 217.116.60.86:16022:
OPTIONS sip:102@192.168.0.96:5062 SIP/2.0
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK600c201d;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as38fdc7e5
To: <sip:102@192.168.0.96:5062>
Contact: <sip:Unknown@109.234.36.15:5060>
Call-ID: 4f3e64754065f8552abe203b5601af48@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Tue, 05 Dec 2017 10:05:45 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:217.116.60.86:16022 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 109.234.36.15:5060;branch=z9hG4bK600c201d;rport
From: "Unknown" <sip:Unknown@109.234.36.15>;tag=as38fdc7e5
To: <sip:102@192.168.0.96:5062>;tag=2942399376
Call-ID: 4f3e64754065f8552abe203b5601af48@109.234.36.15:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.15.1
Content-Length: 0

<------------->
--- (8 headers 0 lines) ---
[2017-12-05 16:05:45] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '102' is now Reachable. (144ms / 2000ms)
Really destroying SIP dialog '4f3e64754065f8552abe203b5601af48@109.234.36.15:5060' Method: OPTIONS



Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 20:04
ded
Кратко выглядит так: Астериск посылает OPTIONS, раз, перепослыает - два
Retransmitting #1 (NAT) to 217.116.60.86:16022: перепосылает ещё раз - три
Retransmitting #2 (NAT) to 217.116.60.86:16022: - нет ответа. И потом ответ ОК всё таки прибегает. НАТ на роутерах - может быть, но скорее всего виноваты сами телефоны. Но запустите в другой сессии
mtr 217.116.60.86 и смотрите в тот момент, когда

Код: Выделить всё

    [2017-12-05 16:30:36] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '109' is now UNREACHABLE!  Last qualify: 74
    [2017-12-05 16:30:36] NOTICE[2764]: chan_sip.c:29729 sip_poke_noanswer: Peer '106' is now UNREACHABLE!  Last qualify: 80
    [2017-12-05 16:30:46] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '101' is now Reachable. (76ms / 2000ms)
    [2017-12-05 16:30:46] NOTICE[2764]: chan_sip.c:23787 handle_response_peerpoke: Peer '109' is now Reachable. (73ms / 2000ms)
У вас телефоны Yealink SIP-W52P 25.73.15.1, такая же история наблюдается со старыми Siemens Gigaset C450 IP. Софт плохо отрабатывает OPTIONS.
пишите в Yealink.

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 20:26
itm
Ded, спасибо за ответ. Дело все в том, что телефоны разные D-Link 150,400, Yealink T19, на DPH400 с доп панелью даже гаснут функциональные клавиши быстрого вызова на 1-2 секунды. pingi до астериска ходят исключительно без потерь, транки а их 30 регистрируются и не отваливаются. С другого офиса регистрировался вообще через PhonerLite.

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 20:39
ded
Что за устройства на 217.116.60.86? Что у них с ресурсами? Память? CPU? Хорошо бы на мониторинг подцепить - zabbix. Если локальная сеть на управляемых свичах, и там есть port mirroringб то можно понаблюдать за трафиком OPTIONS - запросы и ответы. Так ли равномерно они наблюдаются, как их выдаёт Астериск?
Можно проверить версию о "полке" у трафика uploadб если там завелось нечто, торренты, addware, мало ли что. Тогда ответы на OPTIONS будут прерываться.

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 21:33
itm
Стоит в качестве шлюза Cisco asa 5505 (собственно поэтому и Nat, а не тоннель), а дальше через транк в управляемые коммутаторы с разными vlan.
Сеть саму не тестировал, сразу решил с другого офиса протестировать и там проблема повторилась.

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 21:49
ded
asa 5505 теоретически может чудить с DPI. Есть там SIP ALG? SIP helper?
Поднимем IPsec между asa 5505 и вашим Астериск.

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 22:32
gosha
а в `облаке` вашем со временем / таймерами / сетью все хорошо ?

Re: OPTIONS с задержкой

Добавлено: 05 дек 2017, 23:31
ded
gosha, судя по логу - Астериск отправляет то OPTIONS исправно! А ответы ОК морозятся, а потом начинают приходить.

Re: OPTIONS с задержкой

Добавлено: 06 дек 2017, 21:58
w307892309
я бы предложил снять дамп на стороне астериска и посмотреть на время между уходом option и приходом ok (соответствующего)
похожую проблему видел в интернетах, там решилось увеличением таймера t1

Re: OPTIONS с задержкой

Добавлено: 23 дек 2017, 00:12
itm
Проблема все таки была на стороне VDS Хостера(Хотя никакой диагностикой выявить трабл я так и не смог). Создал новую виртуалку, перелил конфиг со старого сервера и проблема исчезла