Lync SIP OPTIONS Requests

Answered Question
дек 8th, 2015
User Badges:

День добрый

Выполняем миграцию Lync 2010 to SfB 2015, возникла проблема при переключения sip trunk, аналогичная этой

https://social.technet.microsoft.com/Forums/lync/en-US/adeca19e-ce8a-40c...

 и

https://social.technet.microsoft.com/Forums/ru-RU/0a32938a-aac9-41f7-bb5...

На текущих dial-peer на lync 

http://www.cisco.com/c/en/us/td/docs/ios/voice/cube/configuration/guide/...

Эта конфигурация с Lync 2010  работает, звонки работают:

В качестве шлюза используется 3925  Version 15.2(4)M4

sip
header-passing
referto-passing
asserted-id pai
options-ping 60
early-offer forced
history-info
midcall-signaling passthru
privacy-policy passthru
!
voice class codec 1000
codec preference 1 g711alaw
codec preference 2 g711ulaw
!
voice class sip-profiles 1000
request INVITE sip-header Diversion remove

dial-peer voice 51001 voip
description ==== to MS Lync ====
preference 1
destination-pattern 5[12349]...
session protocol sipv2
session target ipv4:10.100.2.14:5060
session transport tcp
incoming called-number [189].T
voice-class sip early-offer forced
voice-class sip profiles 1000
voice-class sip block 183 sdp present
voice-class sip options-keepalive up-interval 30 down-interval 65 retry 3
voice-class sip bind control source-interface Loopback0
voice-class sip bind media source-interface Loopback0
dtmf-relay rtp-nte sip-notify sip-kpml
codec g711alaw
no vad
!
dial-peer voice 51002 voip
description ==== to MS Lync ====
huntstop
preference 2
destination-pattern 5[12349]...
session protocol sipv2
session target ipv4:10.100.2.15:5060
session transport tcp
incoming called-number [189].T
voice-class sip early-offer forced
voice-class sip profiles 1000
voice-class sip block 183 sdp present
voice-class sip options-keepalive up-interval 30 down-interval 65 retry 3
voice-class sip bind control source-interface Loopback0
voice-class sip bind media source-interface Loopback0
dtmf-relay rtp-nte sip-notify sip-kpml
codec g711alaw
no vad


После рестарта служба Mediation на серверах SFB 2015 звонки работают какое-то время, однако спустя 5 попыток запроса - в Журнале событий Windows появляется ошибка (От магистрали не получен ответ на запрос OPTIONS, отправленный сервером-посредником.), а затем - В службе сервера-посредника возникла серьезная проблема с подключением к этим кэширующим узлам магистрали MEDIATIONSERVER_GATEWAY_OPTIONS_FAILED.

Такое подозрение, что Cisco gateway не распознает sip запрос от SfB и не отвечает соотв. образом серверам SfB.

Прошу помочь, как решить проблему.

I have this problem too.
0 голоса
Correct Answer by Valery Kuznetsov about 1 год 8 месяцев назад

Вы можете сделать глобальную привязку только для sip, на h323 это не влияет. Настройки на диал-пирах имеют больший приоритет, чем на глобальном уровне. Если на всех ваших SIP диал-пирах уже прописан sip bind control/media, то все должно быть нормально. В любом случае при внесении изменений нужно все проверить и выделить технологическое окно для этих работ.

http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/sip/configuration/15-mt/sip-config-15-mt-book/voi-sip-bind.html

The order of preference for retrieving the SIP signalling and media source address for inbound and outbound calls is as follows: 
•  Bind configuration at dial peer level
•  Bind configuration at global level
•  Best local IP address to reach the destination

Скорее всего нельзя заставить входящие сообщения OPTIONS и ответ на них, заматчить на определенный диал-пир. Поэтому тут сработает конфигурация на глобальном уровне и если ее нет, то сработает Best local IP address.

Correct Answer by Valery Kuznetsov about 1 год 8 месяцев назад

Моя догадка: входящее сообщение OPTIONS не матчится никаким диал-пиром, т.к. фактически это не классический voip звонок. Это видно в логах:

Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: :
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/sipSPIGetPeerByCalledPartyId:
 input arg error
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config:
 MF: Dial-peer is absent..

И чтобы CUBE мог ответить, он сам выбирает лучший интерфейс, но почему-то не может сформировать ответное сообщение.

Вы можете настроить sip bind control/media на глобальном уровне для loopback0 ? И если используете разные диал-пиры к cucm или ITSP прописать на них нужные интерфейсы.

Loading.
Valery Kuznetsov вт, 12/08/2015 - 02:37
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

Добрый день.

После этой ошибки звонки перестают ходить? Нужно смотреть SIP трейсы между шлюзом и Lync.

Соберите debug ccsip messages на шлюзе после рестарта службы и видимо до момента, когда перестают ходить звонки.

Maxim Bezzubov вт, 12/08/2015 - 03:12
User Badges:

перестают, так как Lync помечает шлюз как fail (это и в журнале Windows видно), тут вопрос почему?

дебаг собирал, wireshark смотрел с сервера линка: видно, что линк отправляет запрос sip, но ответа sip 200 ok от шлюза нет!

у меня версия IOS 15.2(4)M4

может нужно обновить?  вижу есть и 15.3 и 15.4 для 3925

просто пока не вижу связи с версией - ведь звонки ходят. что такое может поменяться в CUBE в новой прошивке..

Valery Kuznetsov вт, 12/08/2015 - 03:46
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

А Lync2010 посылал запрос OPTIONS, там был такой функционал? Можно ли его отключить в SfB?

Возможно есть баг в IOS, из-за которого шлюз не отправляет 200 OK. Например, CSCtx79318, но в вашей версии уже должен быть исправлен.



Maxim Bezzubov вт, 12/08/2015 - 04:17
User Badges:

как я понимаю, в линк 2010 не посылал.

Отключить отправку в 2013 Lync server и выше нельзя, как указывает течнет

на течнете скинули проверенную версию IOS для  Lync 2013 

http://technet.microsoft.com/en-gb/lync/gg131938.aspx

сейчас обновил 3925 до 153-3.M4, перезапустил службы на сервере SfB, но ошибки ровно те же самые. Возможно, еще новее версия нужна - 15.4, но она чето пока, кажется, не стабильная, да и вообще не вижу разницы. Может в конфиге все же нужно что-то.

Valery Kuznetsov вт, 12/08/2015 - 05:57
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

Давайте все-таки посмотрим трейсы debug ccsip messages и debug voip ccapi inout со шлюза, когда он получает OPTIONS от Lync.

Maxim Bezzubov вт, 12/08/2015 - 21:11
User Badges:

ок. выкладываю дамп wireshark с сервера SfB и дебаг с циски. Оставил запросы в обе стороны (от и на cisco).

насколько я вижу, циска отправляет SIP/2.0 200 OK, но по wireshark видно, что сервер линка не получает этого. 

Attachment: 
Valery Kuznetsov вт, 12/08/2015 - 23:36
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

SIP/2.0 200 OK это ответ от Lync на запрос OPTIONS от CUBE:

Dec  9 03:11:07.925: //5037/000000000000/SIP/Msg/ccsipDisplayMsg:
Sent:
OPTIONS sip:10.100.2.14:5060 SIP/2.0
Via: SIP/2.0/TCP 172.30.255.8:5060;branch=z9hG4bK760C60
From: ;tag=340DB30-18D
To: 
Date: Wed, 09 Dec 2015 03:11:07 GMT
Call-ID: [email protected]
User-Agent: Cisco-SIPGateway/IOS-15.3.3.M4
Max-Forwards: 70
CSeq: 101 OPTIONS
Contact: <sip:172.30.255.8:5060;transport=tcp>
Content-Length: 0

Dec  9 03:11:07.945: //5037/000000000000/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
FROM: ;tag=340DB30-18D
TO: ;tag=8f6d1429a0
CSEQ: 101 OPTIONS
CALL-ID: [email protected]
VIA: SIP/2.0/TCP 172.30.255.8:5060;branch=z9hG4bK760C60
ACCEPT: application/sdp
CONTENT-LENGTH: 0
ACCEPT-ENCODING: gzip
ACCEPT-LANGUAGE: en
ALLOW: NOTIFY
ALLOW: BENOTIFY
SERVER: RTCC/6.0.0.0 MediationServer


На запросы OPTIONS от 10.100.2.14 CUBE так и не отвечает:

Dec  9 03:13:08.480: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
OPTIONS sip:172.30.255.8 SIP/2.0
FROM: <sip:novlyncfe21.mfnso.local:5060;transport=tcp;ms-opaque=60ae616cdac99fc2>;epid=2616CA72ED;tag=aa467ae3d0
TO: 
CSEQ: 888 OPTIONS
CALL-ID: 6d267d8fd7a54e118b2e15dc3124d9c9
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 10.100.2.14:63223;branch=z9hG4bKbf2729c
CONTACT: <sip:novlyncfe21.mfnso.local:5060;transport=tcp;maddr=10.100.2.14>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/6.0.0.0 MediationServer

Dec 9 03:14:09.760: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: OPTIONS sip:172.30.255.8 SIP/2.0 FROM: <sip:novlyncfe21.mfnso.local:5060;transport=tcp;ms-opaque=60ae616cdac99fc2>;epid=2616CA72ED;tag=2895bcdb7 TO: CSEQ: 889 OPTIONS CALL-ID: 01bb5360bf824ab3974c50d7585fcac2 MAX-FORWARDS: 70 VIA: SIP/2.0/TCP 10.100.2.14:63244;branch=z9hG4bKd05cee35 CONTACT: <sip:novlyncfe21.mfnso.local:5060;transport=tcp;maddr=10.100.2.14> CONTENT-LENGTH: 0 USER-AGENT: RTCC/6.0.0.0 MediationServer

А вот почему так происходит пока непонятно.

Можете уточнить, IP-адрес 172.30.255.8 находится на loopback или реальном интерфейсе?

Valery Kuznetsov ср, 12/09/2015 - 01:16
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

Предлагаю временно отключить options-ping на CUBE и снять debug ccsip all. На входящие сообщения options от lync это не повлияет.

voice service voip
sip
  no options-ping 60

dial-peer voice 51001 voip
no voice-class sip options-keepalive up-interval 30 down-interval 65 retry 3

dial-peer voice 51002 voip
 no voice-class sip options-keepalive up-interval 30 down-interval 65 retry 3


Valery Kuznetsov ср, 12/09/2015 - 03:50
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

По всей видимости CUBE пытается использовать IP-адрес 10.100.254.20 маршрутизатора в качестве source для ответа на запрос OPTIONS.

Я правильно понимаю, что вы не используете sip bind control/media на глобальном уровне?


###
Received:
OPTIONS sip:172.30.255.8 SIP/2.0
FROM: <sip:novlyncfe22.mfnso.local:5060;transport=Tcp;ms-opaque=55fb5b1fd1082691>;epid=BD0A1697E8;tag=1ae03e7a3e
TO: <sip:172.30.255.8>
CSEQ: 1291 OPTIONS
CALL-ID: d359512069b24078981f4f2707604416
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 10.100.2.15:51403;branch=z9hG4bK5c80c840
CONTACT: <sip:novlyncfe22.mfnso.local:5060;transport=Tcp;maddr=10.100.2.15>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/6.0.0.0 MediationServer


Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIAddContextToTable: Added context(0x160B0700) with key=[8108] to table
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/info/4096/ccsip_ipip_media_service_init:
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/info/4096/ccsip_tdmip_media_service_init:
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/verbose/36864/ccsip_ipip_media_forking_init: MF: Queue is initialised..
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.100.2.15,Port 51403, Transport 2, SentBy Port 51403
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/verbose/4608/sipSPISipIncomingMsg: copy the natted transport info to ccb natted dest: 10.100.2.15:51403,natted src: 172.30.255.8:5060, natted transport: 2
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/info/1024/sipSPISipIncomingMsg:  sip via host 10.100.2.15
Dec  9 10:07:49.441: //-1/000000000000/SIP/Info/info/9216/sipSPISipIncomingMsg:  sip nat auto detect 0
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 10.100.254.20 for SIP
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.100.254.20
Dec  9 10:07:49.441: //-1/895416B7AFDA/SIP/State/sipSPIChangeState: 0x160B0700 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.100.2.15,Port 51403, Transport 2, SentBy Port 5060
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPISetDateHeader: Converting TimeZone NOVT to SIP default timezone = GMT
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.100.2.15,Port 51403, Transport 2, SentBy Port 51403
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x30D5B98) counter, current msg->refCount = 2
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
 Freeing NULL pointer!
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.100.2.15:51403, Host:10.100.2.15
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: :
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/sipSPIGetPeerByCalledPartyId:
 input arg error
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/critical/10240/sipSPIGetCallConfig: No match found for P-Called-Party-ID
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/sipSPIUpdateCallInfo:
 input argument error
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media Antitrombone disabled
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder high-density disabled
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 255
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec: MF: Not a Forked SIP leg..
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/8192/sipSPIGetModemConfig:
From Config: Modem NSE payload = 100, Passthrough = 64, Modem relay = 0, Gw-Xid = 1
SPRT latency 200, SPRT Retries = 12, Dict Size = 1024
 String Len = 32, Compress dir = 3
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config:
 MF: Dial-peer is absent..
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state = 0 & New state = -1
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset: MF: Anchor leg config reset done...
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config:
 MF:video profile Dial-peer is absent..
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/8192/sipSPICheckFAAnatAssymetricOrDO2EO: Not a SIP-SIP call or not in FA mode
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/2049/populate_vcc_data: Non dial peer leg - using RTP Supported Codecs
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 18
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 8
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 9
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 4
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 2
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 15
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/1/populate_vcc_data: RTP Preferred Codecs supported by GW 255
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/notify/8192/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/10240/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/2048/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/notify/10240/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x30D5B98) counter, current msg->refCount = 1
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: peer_tag=0
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: ip_best_local_address 10.100.254.20 for SIP
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_media_ip_address_to_bind: return addr 10.100.254.20
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.100.254.20
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: ip_best_local_address 10.100.254.20 for SIP
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/8192/resolve_sig_ip_address_to_bind: return addr 10.100.254.20
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/4096/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/State/sipSPIChangeState: 0x160B0700 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE)
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to table. ccb=0x160B0700 key=d359512069b24078981f4f2707604416 balance 0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable: Adding call id 2307 to table
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38
Dec  9 10:07:49.441: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x30418A4 with refCount = 1
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/info/4096/sipSPISendOptionsResponse: Associated container=0x2F4CB7C to Options Response
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody: sipSPIAppHandleContainerBody len 170
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Transport/sipSPITransportSendMessage: msg=0x30418A4, addr=10.100.2.15, port=51403, sentBy_port=51403, local_addr=, is_req=0, transport=2, switch=0, callBack=0x924C118
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x30418A4 to default port=51403
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting TCP conn create request for addr=10.100.2.15, port=51403, context=0x1564558C
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x15645808,addr=10.100.2.15, port=51403
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer:
Wait Conn Timer started for 5000 msec
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x15645808, connid=-1, addr=10.100.2.15, port=51403, local_addr=, transport=TCP
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.100.2.15, rport:51403 with laddr:
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x160B0700 with connection=0x15645808
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x160B0700 with connection=0x15645808
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Transport/sipTransportLogicSendMsg: Waiting for Connection for sending msg=0x30418A4
Dec  9 10:07:49.445: //8967/895416B7AFDA/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x30418A4
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/get_free_conn_entry: Get first free_index: 1007
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/get_free_conn_entry: Next free_index is 983
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: Add fd 4 connid 1007 to map table [0x15142934]
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: After add new entry, print all the entries in map_tab[4]:
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_add_fd_conn_to_map_tab: fd is 4, connid is 1007
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionCreated: context=0x1564558C
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: gConnTab=0x1564558C, addr=10.100.2.15, port=51403, local_addr=, connid=1007, transport=TCP
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: connection instance created for addr:10.100.2.15, port:51403 local_addr= local_port=58552
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnectionCreated: Moving connection=0x15645808, connid=1007state to pending
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sip_find_connid_by_fd: Map fd 4 to index 1007
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Error/sip_tcp_createconnfailed_to_spi:
 TCP create conn failed to SPI (addr:10.100.2.15, port:51403)
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 57
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionFailed: context=0x1564558C
Dec  9 10:07:49.445: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnFailed: gConnTab=0x1564558C, addr=10.100.2.15, port=51403, local_addr = , transport=TCP
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopConnWaitTimer: Wait timer stopped for connection=0x15645808,addr=10.100.2.15, port=51403
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=1
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostCloseConnection: Posting TCP conn close for addr=10.100.2.15, port=51403, local_addr=, connid=1007
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/sipDeleteConnInstance: Deleted conn=0x15645808, connid=1007, addr=10.100.2.15, port=51403, local_addr=, transport=TCP
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Error/sipTransportPostSendFailure:
 Posting send failure msg with tcb:0x0 reason=4
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x30418A4
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Error/act_options_wait_send_msg_failure:
 Send Error to 10.100.2.15:51403 for transport TCP
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIUdeleteccCallIdFromTable: Removing call id 2307
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIDeleteContextFromTable: Context for key=[8108] removed.
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x160B0700 key=d359512069b24078981f4f2707604416
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x30D5B98
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerUnregisterCtxtInConnection: gConnTab=0x1564558C, addr=10.100.2.15, port=51403, local_addr=, unregistering context=0x160B0700
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Error/sipConnectionManagerUnregisterCtxtInConnection:
 Connection not found for addr=10.100.2.15, port=51403 local_addr=
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Transport/sipSPITransportContextCleanup: Could not purge context gcb=0x160B0700 from the connection; gcb might be locked
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/verbose/1/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/info/8192/sipSPIStopOverlapInfoTimer: Stopping Overlap Info Timer
Dec  9 10:07:49.449: //8967/895416B7AFDA/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x160B0700
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[8108]
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
 Freeing NULL pointer!
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sip_tcp_purge_entry: Socket fd: 4 closed for connid 1007 with address: 10.100.2.15, remote port: 51403
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_rm_fd_to_conn_from_map_tab: Remove fd 4 connid 1007 from map table [0x15142934]
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/ccsip_rm_fd_to_conn_from_map_tab: After remove entry: print all the entries in map_tab[4]:
Dec  9 10:07:49.449: //-1/xxxxxxxxxxxx/SIP/Transport/sip_tcp_purge_entry: last_indx_ccsip_tcp_conn_tab set from 987 to 1007
Maxim Bezzubov ср, 12/09/2015 - 03:59
User Badges:

не используем, только внутри диал-пиров.

как интересно. это IP-адрес линковки шлюза с ASA для DMVPN и в голосе вообще нигде не участвует.

L        10.100.254.20/32 is directly connected, GigabitEthernet0/0.196

и как быть? внутри диал-пиров до линка указано ведь:

voice-class sip bind control source-interface Loopback0
voice-class sip bind media source-interface Loopback0

Correct Answer
Valery Kuznetsov ср, 12/09/2015 - 04:15
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

Моя догадка: входящее сообщение OPTIONS не матчится никаким диал-пиром, т.к. фактически это не классический voip звонок. Это видно в логах:

Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: :
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/sipSPIGetPeerByCalledPartyId:
 input arg error
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall: peer_callID=0
Dec  9 10:07:49.441: //8967/895416B7AFDA/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config:
 MF: Dial-peer is absent..

И чтобы CUBE мог ответить, он сам выбирает лучший интерфейс, но почему-то не может сформировать ответное сообщение.

Вы можете настроить sip bind control/media на глобальном уровне для loopback0 ? И если используете разные диал-пиры к cucm или ITSP прописать на них нужные интерфейсы.

Maxim Bezzubov ср, 12/09/2015 - 20:01
User Badges:

кажется, понял, почему выбирается этот IP: на 3925 есть линковка c ASA (для DMVPN и прочего) и маршруты, в том числе для Loopback, анонсируется как раз через интерфейс 

L        10.100.254.20/32 is directly connected, GigabitEthernet0/0.196

вот на второй 3925

novc3925r03#sh ip ospf 10 neighbor

Neighbor ID Pri State Dead Time Address Interface
172.30.255.8 2 FULL/BDR 00:00:38 10.100.254.20 GigabitEthernet0/0.196

а маршрутится из внутренних сетей на "внешние" сети у нас через ASA

O E2     172.30.255.8 [110/11] via 10.100.254.4, 1d15h, Vlan199

(это sh ip route с внутренних l3 свичей, через которые весь трафик идет из вн. подсетей 10.0.0.0/8)

возможно, вы правы: в диал-пирах в сторону линка (которых явл вх и исхд для звонков линка) там указаны критерии звонка 

destination-pattern 5[12349]...
incoming called-number [189].T

под которые запрос options, выходит, что не попадает.

глобально менять привязку, что-то не очень хороший вариант: у нас на этот шлюз еще завязаны 2 атс внутренние по sip и h323, город, exchange... как бы чего не сломалось (хотя смотрю, что в соотв. диал-пирах указана привязка к нужному интерфейсу, но все же..).

можно как-то по-другому, что если еще диал-пир сделать только для ответа на sip-options lync?

Correct Answer
Valery Kuznetsov ср, 12/09/2015 - 20:27
User Badges:
  • Silver, 250 points or more
  • Почетные Знаки Сообщества,

    Выбор участников, Июль 2015

Вы можете сделать глобальную привязку только для sip, на h323 это не влияет. Настройки на диал-пирах имеют больший приоритет, чем на глобальном уровне. Если на всех ваших SIP диал-пирах уже прописан sip bind control/media, то все должно быть нормально. В любом случае при внесении изменений нужно все проверить и выделить технологическое окно для этих работ.

http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/sip/configuration/15-mt/sip-config-15-mt-book/voi-sip-bind.html

The order of preference for retrieving the SIP signalling and media source address for inbound and outbound calls is as follows: 
•  Bind configuration at dial peer level
•  Bind configuration at global level
•  Best local IP address to reach the destination

Скорее всего нельзя заставить входящие сообщения OPTIONS и ответ на них, заматчить на определенный диал-пир. Поэтому тут сработает конфигурация на глобальном уровне и если ее нет, то сработает Best local IP address.

Maxim Bezzubov ср, 12/09/2015 - 20:42
User Badges:

хорошо, как я понял, нужно сделать

voice service voip
 sip
  bind control source-interface Loopback0
bind media source-interface Loopback0

припоминаю, что есть проблемы с применением привязки, там вроде нужно, чтобы не было активных звонков или что-то такое?

в принципе, посмотрел, на всех sip диал-пирах указаны соотв. привязки, буду надеяться, что все ок будет. проверю.

Действия

Информация о дискуссии