..

decodeMsg error endless loop

..

Developer Group

Developer Group
Connect with thousands of other developers to brainstorm ideas, share best practices and tips - or just chat about the latest emerging technologies making noise in the field. And of course, get the most up-to-date service and support news from Dialogic.
Dialogic Global Call and R4 APIs

decodeMsg error endless loop

  • Hello everyone.

    I'm using HMP SIP IP and hacing some weird issue.

    When system is not in use at all and I have avaiting incoming lines without any calls coming in... after some time  (0-4 days, totally random)

    CPU usage increasing and in logs I'm having the following:

    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:1276      !    -1 ! >> decodeMsg:OnEvent... idx: -1
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:139       !    -1 ! >> decodeMsg: NOT SYSTEM_HANDLE board 1- Sigal SIP [203] -> Sharon [-1]: EvtType_ReleaseCallCmplt
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:272   !     1 ! >> ResourceManager::getCallObjectByAssocElement():   board[1]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:216   !     1 ! >> ResourceManager::getFreeTermCallObject():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:101   !   203 ! >> onStateInit,event=EventRecieveReset:1
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:394   !   203 ! >> performRequestedAction, action=0
    11/25/2015 09:20:50.107  26556       47380 gc_h3r                  ERR1         decoder.cpp:221       !    -1 ! >> decodeMsg(): crn returned on EvtType_ReleaseCallCmplt (BusyRelease) for index=-1 - is NULL
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CAPS   DEBG         sip_caps.cpp:134      !   203 ! SIP_Caps::resetParams()
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_ENCODER DEBG         encoder.cpp:4036      !     0 ! << sendIpcMsg(): Board 1 - Sharon [5001] -> Sigal SIP [203] : MsgType_ReleaseCall (10)
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_IPC     DEBG         ipc.cpp:165           !     0 ! sendMsg : m_Socket = 2248 , sizeOfMsg = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IE     DEBG         sip_info_elemen:229   !   203 ! >>  SipInfoElement::reset() including MIME buffers,m_SipHeaderMgrIn is 0x0D0EA1F8, m_SipHeaderMgrOut is 0x0D0EA258
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SIGNAL DEBG         sip_signaling.c:1353  !   203 ! Entering SipSignaling::releaseCall - m_hCallLeg=0x0
    11/25/2015 09:20:50.107  26556       12896 gc_h3r                  WARN         sip_signaling.c:1364  !   203 ! SipSignaling::releaseCall: BAD m_hsCall PARAM
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_IPC     DEBG         ipc.cpp:190           !     0 ! sendMsg : bytes attempted = 24 sent = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:383   !     1 ! >> ResourceManager::markCallObjectAsBusy():   board[1]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_ENCODER DEBG         encoder.cpp:440       !   203 ! << sendBusyReleaseMsg() [0]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:491   !     1 ! >> ResourceManager::markTermCallObjectAsFree():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:2565  !   203 ! << freeResourcesAndGoIdle: [0]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:1301      !    -1 ! << decodeMsg::OnEvent: [0] EXIT
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:45        !     0 ! recvCB : Board 1 - fdHandle = 844
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..EC DEBG         sip_decoder.cpp:585   !   203 ! >> Decode Msg: Sharon [5001] -> SipSigal [203] : MsgType_ReleaseCall (10)
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:346   !     1 ! >> ResourceManager::associateCallObjectByIndex():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r                  WARN         resource_mgr.cp:367   !     1 ! << ResourceManager::associateCallObjectByIndex():   assocElementIndex[5001] out of range
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:1930  !   203 ! >> onReleaseCallMsg:
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:174   !   203 ! >> onStateWaitCall : ev EventIPCreleaseCall
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..NC DEBG         sip_encoder.cpp:214   !   203 !  SIP_ENCODER::sendMsgHeader() - Msg: Sigal [203] -> Sharon [-1] : EvtType_ReleaseCallCmplt (93)
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:241       !     0 ! sendMsg : m_Socket = 844 , sizeOfMsg = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:257       !     0 ! sendMsg : bytes attempted=24 sent = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..NC DEBG         sip_encoder.cpp:3436  !   203 ! << SipEncoder::sendReleaseCallCmplt [0]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:76    !   203 ! >> reset
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:1276      !    -1 ! >> decodeMsg:OnEvent... idx: -1
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:139       !    -1 ! >> decodeMsg: NOT SYSTEM_HANDLE board 1- Sigal SIP [203] -> Sharon [-1]: EvtType_ReleaseCallCmplt
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:272   !     1 ! >> ResourceManager::getCallObjectByAssocElement():   board[1]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:216   !     1 ! >> ResourceManager::getFreeTermCallObject():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:101   !   203 ! >> onStateInit,event=EventRecieveReset:1
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:394   !   203 ! >> performRequestedAction, action=0
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CAPS   DEBG         sip_caps.cpp:134      !   203 ! SIP_Caps::resetParams()
    11/25/2015 09:20:50.107  26556       47380 gc_h3r                  ERR1         decoder.cpp:221       !    -1 ! >> decodeMsg(): crn returned on EvtType_ReleaseCallCmplt (BusyRelease) for index=-1 - is NULL
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IE     DEBG         sip_info_elemen:229   !   203 ! >>  SipInfoElement::reset() including MIME buffers,m_SipHeaderMgrIn is 0x0D0EA1F8, m_SipHeaderMgrOut is 0x0D0EA258
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_ENCODER DEBG         encoder.cpp:4036      !     0 ! << sendIpcMsg(): Board 1 - Sharon [5001] -> Sigal SIP [203] : MsgType_ReleaseCall (10)
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SIGNAL DEBG         sip_signaling.c:1353  !   203 ! Entering SipSignaling::releaseCall - m_hCallLeg=0x0
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_IPC     DEBG         ipc.cpp:165           !     0 ! sendMsg : m_Socket = 2248 , sizeOfMsg = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r                  WARN         sip_signaling.c:1364  !   203 ! SipSignaling::releaseCall: BAD m_hsCall PARAM
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:383   !     1 ! >> ResourceManager::markCallObjectAsBusy():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:491   !     1 ! >> ResourceManager::markTermCallObjectAsFree():   board[1]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_IPC     DEBG         ipc.cpp:190           !     0 ! sendMsg : bytes attempted = 24 sent = 24
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_ENCODER DEBG         encoder.cpp:440       !   203 ! << sendBusyReleaseMsg() [0]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:1301      !    -1 ! << decodeMsg::OnEvent: [0] EXIT
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:2565  !   203 ! << freeResourcesAndGoIdle: [0]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:45        !     0 ! recvCB : Board 1 - fdHandle = 844
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..EC DEBG         sip_decoder.cpp:585   !   203 ! >> Decode Msg: Sharon [5001] -> SipSigal [203] : MsgType_ReleaseCall (10)
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:346   !     1 ! >> ResourceManager::associateCallObjectByIndex():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r                  WARN         resource_mgr.cp:367   !     1 ! << ResourceManager::associateCallObjectByIndex():   assocElementIndex[5001] out of range
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:1930  !   203 ! >> onReleaseCallMsg:
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CA..GR DEBG         sip_callmanager:174   !   203 ! >> onStateWaitCall : ev EventIPCreleaseCall
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..NC DEBG         sip_encoder.cpp:214   !   203 !  SIP_ENCODER::sendMsgHeader() - Msg: Sigal [203] -> Sharon [-1] : EvtType_ReleaseCallCmplt (93)
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:241       !     0 ! sendMsg : m_Socket = 844 , sizeOfMsg = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_IPC    DEBG         sip_ipc.cpp:257       !     0 ! sendMsg : bytes attempted=24 sent = 24
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_SI..NC DEBG         sip_encoder.cpp:3436  !   203 ! << SipEncoder::sendReleaseCallCmplt [0]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:1276      !    -1 ! >> decodeMsg:OnEvent... idx: -1
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       SH_DECODER DEBG         decoder.cpp:139       !    -1 ! >> decodeMsg: NOT SYSTEM_HANDLE board 1- Sigal SIP [203] -> Sharon [-1]: EvtType_ReleaseCallCmplt
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:272   !     1 ! >> ResourceManager::getCallObjectByAssocElement():   board[1]
    11/25/2015 09:20:50.107  26556       47380 gc_h3r       COM_R_MGR  DEBG         resource_mgr.cp:216   !     1 ! >> ResourceManager::getFreeTermCallObject():   board[1]
    11/25/2015 09:20:50.107  26556       12896 gc_h3r       SIP_CH_MGR DEBG         sip_channelmana:76    !   203 ! >> reset
    11/25/2015 09:20:50.107  26556       47380 gc_h3r                  ERR1         decoder.cpp:221       !    -1 ! >> decodeMsg(): crn returned on EvtType_ReleaseCallCmplt (BusyRelease) for index=-1 - is NULL

    This is not affecting any channel - they are all operational. Under full load (inbound/outbound) same behaviour. No errors on application side.

    So I assume that is some error loop at driver level.

    Pretty obvious that this situation being caused by "hackers" sending wrong SIP messages (SPD or anything).

    However in my situation I'm not able to block incoming calls and should accept them from any sources.

    To remove that issue gc_Stop/gc_Start should be performed. HMP services restart not required.

    So my question is there any workaround or any thoughts on this problem?

  • Yes, it is odd. Did you check wireshark to see what messages may cause those spikes?

    Global Call / GC IP are not enabled in RTF; I wonder if your app sees some unexpected events when such attacks occur?

    You may try to change the default SIP port on the gateway and the app to, say, 5061 and see if the problem persists. I'd also try TCP as a SIP transport, if your setup allows that.  

  • Thank you for your reply.

    Unfortunately TCP not an option. I will try changing port but most likely they are just looking for any opened ones (it is really random in time so specific attack excluded at this point, I guess just port scan and then regular bots for VoIp).

    Global Call / GC IP not giving any info during error. that trace is the only "active" ones I saw.

    I can't track exact moment of an issue because no signal or error coming to the app (I guess happens just in between waitcall and accept), and then log being overwritten in no time (1K+ messages per second lol).

    I had an idea to reject call somehow after waitcall before doing any accept. but was not able to find any good way. Is there any?

  • You can try to cancel WitCall as it described in 1.60 at www.dialogic.com/.../release_update.pdf

  • Well technically that is not my case. WaitCall cancellation not required. Once call comes in I'm retrieving proper CRN and DNIS. After that I'm able to filter "bad" calls and somehow reject them. Probably that will eliminate this behaviour. However dropping call (drop/release) after waitcall and prior to accept causing some handlers leack and in 1-2 days (with high density of incoming calls) dialogic starting to have lack of resources issues.

    Maybe I'm missing some other proper way to drop incoming call without accepting it?

    P.S. just to clarify by "accepting" i mean proper gc_WaitCall->gc_AnswerCall sequence. After that I can drop call and everything works as expected.

    Problem is I did not find proper way to drop call after gc_WaitCall and prior to gc_AnswerCall

  • Are you saying you need to gc_DropCall right after GCEV_OFFERED? If so, the app MUST specify a reason for rejection, if not, by default the stack would try to send BYE, which is not allowed in this state, and therefore this message, being allocated in GC libs, is never released, since there is no response from SIP network. This may cause a leak (a bit speculating, since didn't see the logs, but it is possible).

    If you need to reject an inbound call in OFFERED state (before accepting it), you need to specify one of the cause code with gc_DropCall. Please refer ch. 11 at www.dialogic.com/.../globalcall_for_ip_hmp_v12.pdf for a list of valid codes, pick what seems to be relevant, for example, PEC_SIPReasonStatus403Forbidden. See the whole list in ch 11.5 at the location above

  • Oh that is great suggestion and makes perfect sense about inability to send BYE. I will try it out and update you with the results.

  • What HMP SU version is this?   What is the O/S?   There have been some work done in addressing resource allocation errors/leak within the last year.

    Jeff

  • Windows 2008 R2 64bit. SU - 361

    So far Lenids suggestion works good. I'm doing reject in offered state and not having any issues.

    Will keep it running for this week to make absolutely sure.

  • So after I started doing reject in offered state for inbound calls with Forbidden403 reason it became good and no more "decodeMsg" happened.

    However after 5 days of testing I got same issue with placing calls degradation. In logs I have the following:

    12/01/2015 10:18:47.043  55424       45800 gc_h3r                  ERR1         sip_signaling.c:189   !    79 ! SipSignaling::makeCall: RvSipCallLegMgrCreateCallLeg Failed

    12/01/2015 10:18:47.043  55424       45800 gc_h3r                  ERR1         sip_callmanager:816   !    79 ! << onMakeCallMsg: m_pSignaling->makeCall failed: [-996]

    12/01/2015 10:18:47.043  55424       45800 gc_h3r                  ERR1         sip_decoder.cpp:1661  !    79 ! << SIP_DECODER::postMakeCall(): m_pCallManager->onMakeCallMsg() failed: -996

    12/01/2015 10:18:47.043  55424       45800 gc_h3r                  ERR1         sip_decoder.cpp:777   !    79 ! << SIP_DECODER::decodeMsg(): postMakeCall() failed

    12/01/2015 10:18:47.043  55424       45800 gc_h3r                  ERR1         sip_ipc.cpp:311       !     0 ! recv :error on decodeMsg

    Same issue I got earlier with "NORMAL CLEARING" as mentioned above.

    Any ideas why this happens?

  • Looks like you system might be leeking call-legs, or all have been consumed and non are available for new calls. There might be some additional issue unknown occurring on your system right now leading to this behavior (for instance mis handled sip messages). Really the only way to handle this going forward due to its complexity, is to reported the issue to technical support team at Dialogic. However that would require that you have a Service Level agreement (tied to the HMP license on the server) with them in order to have the issue reviewed. Here is a link to more information on that:

    www.dialogic.com/.../HMP-SR140-enterprise-software-services.htm

    Ideally, debugging this type of issue via forum at this point get a bit too involved since a lot of lower level logging and analysis would need to be done at this point (back and forth). And that is not the point of the "developers forum" to debug run time live site issues.

    Regards,

    Jeff

  • That is understandable. Thank you regardless.

  • Updating for those who may fall into the same issue:

    My application not expecting GCEV_EXTENSION events neither SUBSCRIBE or NOTiFY. However those "bad" inbound callers also sending those as I figured.

    When going through regular gc_Answer->gc_DropCall process call-leg being cleared properly (at least I'm not noticing anything). Once I'm starting to make early reject (at OFFERED state). those GCEV_EXTENSION events starting to occupy legs forever and causing system degradation as described in docs.

    So final solution is to make early reject + always check for GCEV_EXTENSION events and process them regardless if they are expected or not.

    Thanks Jeff and Leonid for ideas and help.

  • Yea, I was going to ask about other unhandled messages (notify/subscribe) in this case which might be sent to the system. That commonly happens when connected to gateways/switches. Thus you are correct in saying that call-legs are being allocated and not released since its not handled at the application level. That part needs to be added in order to address that part of the issue.

    Jeff

  • Was still causing high CPU load... this finally fixed in SU375