[cisco-voip] SIP OPTIONS pings are blocked on Cisco CUBE 3945E - Resource failure, dropping OPTIONS
Maciej Bylica
mbgatherer at gmail.com
Tue Oct 9 14:11:18 EDT 2018
Thanks for prompt answer.
No, i am not using CCP.
As i see OPTIONS ping does not match with any dialpeer
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/1024/ccsipInitPldCallingInfo: non-numeric
calling number: *stringhere*
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA
URL:sip:10.10.10.10:5060, Host:100.64.4.31
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match
incoming dialpeer for Calling number: : *stringhere*
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Error/sipSPIGetPeerByCalledPartyId:
input arg error
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/critical/10240/sipSPIGetCallConfig: No match
found for P-Called-Party-ID
Oct 9 17:50:04.068: //3652/95FFAA748E45/SIP/Error/sipSPIUpdateCallInfo:
input argument error
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition
tag absent in Require/Supported header
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media
Antitrombone disabled
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the
configured mode as FLOW-THROUGH
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder
high-density disabled
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode
set to FLOW_THROUGH
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer
leg - using RTP Supported Codecs
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 18
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 0
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 8
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 9
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 4
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 2
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 15
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
Codecs supported by GW 255
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec:
MF: Not a Forked SIP leg..
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp
configure for this leg.
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall:
peer_callID=0
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config:
MF: *Dial-peer is absent*..
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state
= 0 & New state = -1
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset:
MF: Anchor leg config reset done...
Oct 9 17:50:04.068:
//3652/95FFAA748E45/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config:
MF:video profile Dial-peer is absent..
OPTIONS looks like following:
OPTIONS sip:domain.name.here:5060 SIP/2.0
From: <sip:*stringhere*@domain.name.here>;tag=4a6000292f6a
To: <sip:*stringhere*@domain.name.here>
I do not have any script in use there, the configuration in pretty basic.
What i have found is that second OPTIONS (the one that is left/dropped
without OK) also generates following output:
Oct 9 17:50:38.070:
//-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor:
Checking Invite Dialog
Oct 9 17:50:38.070:
//3653/9862338A8E46/SIP/Info/verbose/4096/sipSPIFindCcbUASReqTable:
*****CCB found in UAS Request table. ccb=0x2766B958
Oct 9 17:50:38.070:
//3653/9862338A8E46/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying
with child CCB 0x0 index 0 curr_child 0
Oct 9 17:50:38.070: //3653/9862338A8E46/SIP/Error/sipSPICheckFromToRequest:
Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL
old_from: <sip:*stringhere*@domain.name.here>;tag=4a6000292f6a
old_to: <sip:*stringhere*@domain.name.here>;tag=D7E844-1438
new_from: <sip:*stringhere*@domain.name.here>;tag=6c7f09452671
new_to: <sip:*stringhere*@domain.name.here>
....
Oct 9 17:50:04.068: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
Freeing NULL pointer!
Could you please point me where i can find some information how to create
such dial-peer for OPTIONS or give me a brief example of this configuration
please.
Thanks
Maciej.
wt., 9 paź 2018 o 16:39 Nick Barnett <nicksbarnett at gmail.com> napisał(a):
> Are you using Customer Call Back? Which dial peer is the options ping
> hitting? Does that dial peer have the CCB script on it? If so... maybe make
> another dial peer for options pings that does not have the script enabled.
> This is just a hunch...
>
> On Tue, Oct 9, 2018 at 6:50 AM Maciej Bylica <mbgatherer at gmail.com> wrote:
>
>> Hi
>>
>> I have really strange problem with SIP OPTIONS pings.
>> The Cisco i have (CUBE 3945 ios Version 15.3(3)M5) responds only to the
>> first OPTIONS packet that is received from the endpoint.
>> The rest of OPTIONs are dropped with following debug output:
>>
>> Oct 9 12:52:06 10.10.10.10 8694907: Oct 9 10:55:58.194:
>> //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI :
>> SIPSPI_EV_CC_OPTIONS_RESP
>> Oct 9 12:52:06 10.10.10.10 8694908: Oct 9 10:55:58.194:
>> //148025/BCB3C79A92C0/SIP/Info/info/4096/sact_idle_new_message_options:
>> ccsip_api_options_ind returned: SIP_SUCCESS
>> Oct 9 12:52:06 10.10.10.10 8694909: Oct 9 10:55:58.194:
>> //148025/BCB3C79A92C0/SIP/State/sipSPIChangeState: 0x258D7210 : State
>> change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT,
>> SUBSTATE_NONE)
>> Oct 9 12:52:06 10.10.10.10 8694910: Oct 9 10:55:58.194:
>> //148025/BCB3C79A92C0/SIP/Error/sipSPIUaddCcbToTable:
>> Oct 9 12:52:06 10.10.10.10 8694911: *Could not add ccb to table*.
>> ccb=0x258D7210
>> key=c3c4f5582a4bfa1ff4b7e741c3cb6c6822f738b4cd7e78633fc70f5441197d3
>> Oct 9 12:52:06 10.10.10.10 8694912: Oct 9 10:55:58.194:
>> //148025/BCB3C79A92C0/SIP/Error/sact_idle_new_message_options:
>> Oct 9 12:52:06 10.10.10.10 8694913: *Resource failure, dropping
>> OPTIONS*
>>
>> The true is that Cisco receives quite significant amount of SIP OPTIONs
>> from the endpoint in short time, like 10 OPTIONS packeges within
>> miliseconds.
>> The after-effect i want to achieve is a response for each incoming OPTIONS
>>
>> Example of a successful response:
>> Oct 9 11:30:37 10.10.10.10 8625106: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI :
>> SIPSPI_EV_CC_OPTIONS_RESP
>> Oct 9 11:30:37 10.10.10.10 8625107: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Info/info/4096/sact_idle_new_message_options:
>> ccsip_api_options_ind returned: SIP_SUCCESS
>> Oct 9 11:30:37 10.10.10.10 8625108: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/State/sipSPIChangeState: 0x258B1110 : State
>> change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT,
>> SUBSTATE_NONE)
>> Oct 9 11:30:37 10.10.10.10 8625109: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to
>> table. ccb=0x258B1110
>> key=c3c4f5582a4bfa1ff4b7e741c3cb6c6822f738b4cd7e78633fc70f5441197d3 balance
>> 1
>> Oct 9 11:30:37 10.10.10.10 8625110: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable:
>> Adding call id 23DA9 to table
>> Oct 9 11:30:37 10.10.10.10 8625111: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event:
>> ccsip_spi_get_msg_type returned: 3 for event 38
>> Oct 9 11:30:37 10.10.10.10 8625112: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created
>> msg=0x203FFDA4 with refCount = 1
>> Oct 9 11:30:37 10.10.10.10 8625113: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Info/info/4096/sipSPISendOptionsResponse:
>> Associated container=0x2673A528 to Options Response
>> Oct 9 11:30:37 10.10.10.10 8625114: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody:
>> sipSPIAppHandleContainerBody len 164
>> Oct 9 11:30:37 10.10.10.10 8625115: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Transport/sipSPITransportSendMessage:
>> msg=0x203FFDA4, addr=11.11.11.11, port=5060, sentBy_port=5060, local_addr=,
>> is_req=0, transport=1, switch=0, callBack=0x4F48054
>> Oct 9 11:30:37 10.10.10.10 8625116: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP
>> extension config:1, check sys cfg:1
>> Oct 9 11:30:37 10.10.10.10 8625117: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Transport/sipSPITransportSendMessage: Proceedable
>> for sending msg immediately
>> Oct 9 11:30:37 10.10.10.10 8625118: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Transport/sipTransportLogicSendMsg: Trying to
>> send resp=0x203FFDA4 to default port=5060
>> Oct 9 11:30:37 10.10.10.10 8625119: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection:
>> connection required for raddr:11.11.11.11, rport:5060 with laddr:
>> Oct 9 11:30:37 10.10.10.10 8625120: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering
>> gcb=0x258B1110 with connection=0x2426673C context list
>> Oct 9 11:30:37 10.10.10.10 8625121: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Transport/sipTransportLogicSendMsg: Connection
>> obtained...sending msg=0x203FFDA4
>> Oct 9 11:30:37 10.10.10.10 8625122: Oct 9 09:34:28.569:
>> //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send
>> for msg=0x203FFDA4, addr=11.11.11.11, port=5060, local_addr=, connId=2 for
>> UDP
>> Oct 9 11:30:37 10.10.10.10 8625123: Oct 9 09:34:28.569:
>> //146857/5A42A0608E30/SIP/Msg/ccsipDisplayMsg:
>> Oct 9 11:30:37 10.10.10.10 8625124: Sent:
>> Oct 9 11:30:37 10.10.10.10 8625125: SIP/2.0 200 OK#015
>>
>> Could someone help me with this? I really appreciate your advice.
>>
>> Maciej
>> _______________________________________________
>> cisco-voip mailing list
>> cisco-voip at puck.nether.net
>> https://puck.nether.net/mailman/listinfo/cisco-voip
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20181009/f9b04932/attachment.html>
More information about the cisco-voip
mailing list