Certain SIP calls hit Auto Attendant, then never disconnect Urgent

rpavlinich · Feb 25, 2014

Has anyone ever encountered an issue like this? My cuustomer has had 2 calls that say they have been active for 13 days, one for 5 days, and one for 3 days. All of them are stuck at their Main AA, or so says System Status. This customer only has 4 VM ports, so no one can now access VM, calls are not being routed to the AA now, etc. This is the second time this has happened. Last time I cleared the calls with System Status and started up Sysmon to record the details if it ever happened again(which it has, obviously), and had it save hourly logs.

Now, not only am I working with an issue that none of my tech support resources have ever heard of, but the customer is going to receive and astronomical phone bill.

Detail:
IP Office 500
Release 5.0(26)
Embedded VM with 4 ports
NexVortex SIP Trunks

This is the most recent call that did not disconnect:

F:\JHC\JHC_Call_Details_20140225_070713.txt
Call Details, JHC (Internal IP)
2/25/2014 3:07:13 PM
-------------------------------------------

Call Details

Call Ref: 5471 Call length: 3 days 18:42:35

Originator
Current State: Connected Time in State: 3 days 18:42:35
Trunk: Line: 18 SIP px3.nexvortex.com Group: 1 Channel: 5
Incoming Caller ID: CallingNumber@Caller's IP
Incoming DID: Customer's Main Number@Customer's IP Address

Destination
Current State: Connected Time in State: 3 days 18:42:35
Currently at: Auto Attendant MainAA

Call target / Routing information
Original Target: Shortcode Feature *3, AutoAttendant, System
Call Recording: No
Redirecting Station: MainAAUser
Redirected to Twin: No
Routed across SCN trunk: No
Retargeting Count: 0

Trace Output:

Here is an excerpt what one of the logs, detailing call 5471:

1389779776mS CMCallEvt: CREATE CALL:5471 (f54f4728)
1389779776mS CMCallEvt: 0.22288.0 -1 BaseEP: NEW CMEndpoint f54be19c TOTAL NOW=11 CALL_LIST=4
1389779778mS CMLineRx: v=0
CMSetup
Line: type=IPLine 18 Call: lid=18 id=22287 in=1
Called[Customer's Main Number] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[XXXXX@X.X.X.X] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name="Name of Caller"
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=XXXXX@X.X.X.X
IE CMIEFastStartInfoData (6)
IE CMIEMediaWaitForConnect (16) CMIEMediaWaitForConnect
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=5 class=CMDeviceSIPTrunk type=0 number=18 channel=0 rx_gain=32 tx_gain=32 ep_callid=22287 ipaddr=Internal IP apps=0
1389779778mS CD: CALL: 18.22287.1 BState=Idle Cut=1 Music=0.0 Aend="Line 18" (0.0) Bend="" [] (0.0) CalledNum=Customer's Main Number () CallingNum=XXXXX@X.X.X.X ("Name of Caller") Internal=0 Time=2 AState=Idle
1389779779mS CMCallEvt: 18.22287.1 5471 SIPTrunk Endpoint: StateChange: END=A CMCSIdle->CMCSDialInitiated
1389779779mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: LOOKUP CALL ROUTE: type=0 called_party=Customer's Main Number sub= calling=XXXXX@X.X.X.X dir=in complete=1 ses=0
1389779779mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: SET BESTMATCH: length 11 vs -1 match=Customer's Main Number dest=MainAACFWD
1389779779mS CMCallEvt: Priority hike: call 5471 priority 0->1
1389779780mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: LOOKUP ICR: DDI=Customer's Main Number@External IP CGPN=XXXXX@X.X.X.X (Destination MainAACFWD ) => CDPN=MainAACFWD
1389779780mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: ADD TARGET (N): number=MainAACFWD type=0 depth=1 nobar=1 setorig=1 ses=0
1389779780mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: HG(MainAACFWD,210,Internal IP) Requires Routing To Master(1). IsLocalExecutive(1)
1389779780mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: HG call targeting occuring here
1389779781mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: PrimeForHGTarget: MainAACFWD setorig=1 recall=0 resetExtnVars 1
1389779781mS CMCallEvt: Priority hike: call 5471 priority 1->5
1389779781mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: AddHGTarget MainAACFWD (depth=2) allowq=1 type=CMNTypeUnknown
1389779781mS CMCallEvt: 0.22289.0 -1 BaseEP: NEW CMEndpoint f55cb330 TOTAL NOW=12 CALL_LIST=5
1389779782mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: AddHGTargetRingRotary(Sequential) MainAACFWD ring_attempt_count 0 index 0
1389779782mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: ADD USER: MainAAUser depth=3 disallow_cw=1 dnd=0 real_call=1 group_call=1 type(CMNTypeUnknown) incl(0x0) excpt(0x34), allow_redir(1) remote=00000000
1389779782mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: ADD TARGET (N): number=*3 type=100 depth=4 nobar=1 setorig=0 ses=0
1389779783mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: SYS SC: *3 2 sc=type=AutoAttendant code=*3, num=AA:MainAA callinfop->sending_complete=1 secondary_dialtone=
1389779783mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: ADD VM TARGET
1389779783mS CMTARGET: **** 18.22287.1 5471 SIPTrunk Endpoint: MakeVoicemailTarget pbx=<null> local=1 type=3
1389779784mS CMMap: a=4.3 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 5, total 8
1389779784mS CMCallEvt: 0.22290.0 -1 BaseEP: NEW CMEndpoint f55065b4 TOTAL NOW=13 CALL_LIST=5
1389779784mS CMTARGET: 0.22290.0 5471 RAS.0: ADD PRIMARY
1389779785mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: ADD VM TARGET: SUCCEEDED
1389779785mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: INITIAL TARGETING SUCCEEDED
1389779785mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: GetNoAnswerTimer:15
1389779786mS CMCallEvt: 18.22287.1 5471 SIPTrunk Endpoint: StateChange: END=A CMCSDialInitiated->CMCSDialled
1389779787mS CMLineTx: v=0
CMProceeding
Line: type=IPLine 18 Call: lid=18 id=22287 in=1
1389779787mS CMCallEvt: 0.22288.0 5471 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
1389779788mS CMCallEvt: 0.22290.0 5471 RAS.0: StateChange: END=T CMCSIdle->CMCSOffering
1389779788mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 0->22290 )
1389779789mS CMExtnTx: v=RAS, p1=0
CMSetup
Line: type=RAS 1 Call: lid=0 id=1014 in=0
Called[#AA:MainAA] Type=Voicemail (102) Reason=CMDRX_Attendant SndComp Calling[XXXXX@X.X.X.X] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=21 chan=12
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name="Name of Caller"
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=XXXXX@X.X.X.X
IE CMIEMediaWaitForConnect (16) CMIEMediaWaitForConnect
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=5 class=CMDeviceSIPTrunk type=0 number=18 channel=0 rx_gain=32 tx_gain=32 ep_callid=22287 ipaddr=Internal IP apps=0
IE CMIECalledPartyName (224)(Type=CMNameDefault) name=MainAAUser
IE CMIECallingPartyName (110)(Type=CMNameDefault) name="Name of Caller"
IE CMIEOriginalCalledPartyName (236)(Type=CMNameDefault) name=MainAACFWD
IE CMIEOriginalCalledPartyNumber (238)(P:100 S:100 T:101 N:100 R:1) number=210
IE CMIERedirectingPartyName (232)(Type=CMNameDefault) name=MainAACFWD
IE CMIERedirectingPartyNumber (234)(P:100 S:100 T:101 N:100 R:1) number=210
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=Customer's Main Number@External IP
IE CMIEMohSourceId (247) MOH Source = 1
Display ["Name of Caller">MainAACFWD]
Timed: 21/02/14 12:24
Locale: enu
1389779789mS CMMap: a=21.12 b=1.254 T
1389779791mS PRN: Task Daemon waiting on Call Model Semaphore held by CMRtEngine
1389779793mS CMExtnRx: v=RAS, p1=0
CMConnect
Line: type=RAS 1 Call: lid=0 id=1014 in=0
1389779794mS CMCallEvt: 0.22290.0 5471 RAS.0: StateChange: END=T CMCSOffering->CMCSConnReq
1389779794mS CMCallEvt: 0.22288.0 5471 TargetingEP: RequestEnd 0.22290.0 5471 RAS.0
1389779794mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: Removed HG from Callinfo
1389779794mS CMCallEvt: 0.22289.0 5471 ACDTep(MainAACFWD): StateChange: END=??? CMCSIdle->CMCSDelete
1389779795mS CMCallEvt: 0.22289.0 -1 BaseEP: DELETE CMEndpoint f55cb330 TOTAL NOW=12 CALL_LIST=5
1389779795mS CMTARGET: 18.22287.1 5471 SIPTrunk Endpoint: CancelTimer CMTCNoAnswerTimeout
1389779795mS CMCallEvt: 0.22288.0 -1 BaseEP: DELETE CMEndpoint f54be19c TOTAL NOW=11 CALL_LIST=5
1389779796mS CMExtnEvt: v=1014 State, new=Connected old=Idle,0,0,RAS
1389779796mS CMCallEvt: 18.22287.1 5471 SIPTrunk Endpoint: StateChange: END=A CMCSDialled->CMCSOGConnReq
1389779798mS CMLineTx: v=0
CMConnect
Line: type=IPLine 18 Call: lid=18 id=22287 in=1
BChan: slot=21 chan=12
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=#AA:MainAA
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=#AA:MainAA
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=5 class=CMDeviceVoicemail type=0 number=0 channel=12 rx_gain=32 tx_gain=32 ep_callid=22290 ipaddr=Internal IP apps=0
IE CMIERedirectingPartyName (232)(Type=CMNameDefault) name=MainAACFWD
IE CMIERedirectingPartyNumber (234)(P:100 S:100 T:101 N:100 R:1) number=210
IE CMIEFastStartInfoData (6)
1389779799mS CD: CALL: 18.22287.1 BState=Connected Cut=3 Music=0.0 Aend="Line 18" (0.0) Bend="MainAACFWD(210)" [VoiceMail] (21.12) CalledNum=#AA:MainAA (MainAAUser) CallingNum=XXXXX@X.X.X.X ("Name of Caller") Internal=0 Time=23 AState=Connected
1389779800mS H323Evt: SetRfc2833 (1): rx payload 101 tx payload 101
1389779800mS CMMap: PCG::MapBChan pcp[555]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
1389779801mS CMMap: PCGS CPReserveCodec for the other end (pcp[555]b0r1) true
1389779801mS CMMap: PCG::MapBChan pcp[47]b1r0 cp_b f59f9158 other_cp_b f5a027fc type CGTypeSimple
1389779801mS CMMap: a=4.3 b=21.12 M1
1389779801mS CMMap: PlatformConnectionAudioSAP::ConnectVoice (connect) pcp[555]b0r1 echo_cancellation set to 0
1389779801mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[555]b0r1 Configure 4.3
1389779801mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[555]b0r1 ConnectIndication 4.3
1389779802mS PRN: Config Write Wake Up
1389779901mS PRN: Form Fail Response
1389779937mS SIP Tx: UDP Internal LAN IP:5060 -> Customer's WAN IP:5060
SIP/2.0 200 Ok
Via: SIP/2.0/UDP Customer's WAN IP:5060;branch=z9hG4bK57a9.f728edf5.0
Via: SIP/2.0/UDP Other IP:5060;branch=z9hG4bK57a9.792b2627.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bce064d8c9eea6c79
Record-Route: <sip:+Customer's Main Number@Customer's WAN IP:5060;nat=yes;ftag=gK02292d1c;lr=on>
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29919 INVITE
Contact: "+Customer's Main Number" <sip:+Customer's Main Number@External IP:5060;transport=udp>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, INFO
Content-Type: application/sdp
Content-Length: 229

v=0
o=UserA 3086211473 4142208928 IN IP4 External IP
s=Session SDP
c=IN IP4 External IP
t=0 0
m=audio 49160 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
1389780013mS PRN: Form Fail Response
1389780198mS RES: Fri 21/2/2014 12:24:41 FreeMem=70636384(1) CMMsg=5 (5) Buff=200 950 999 7470 5 Links=19094
1389780198mS RES2: IP 500 5.0(26) Tasks=31 RTEngine=0 CMRTEngine=0 Timer=47 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
1389780302mS PRN: Updates IO list size 0 updated list size 1
1389780302mS PRN: Config Write Completed
1389780652mS PRN: Form Fail Response
1389780777mS PRN: Form Fail Response
1389780955mS H323Evt: RTP(50t): Internal LAN IP/49160 4.55.42.2/22236 CODEC=G729A8K(6) PKTSZ=20 RFC2833=on AGE=1155 SENT=50 (avg size=20) RECV=0 (avg size=0)
1389781401mS PRN: Form Fail Response
1389781542mS PRN: Form Fail Response
1389781756mS PRN: Form Fail Response
1389781901mS PRN: Form Fail Response
1389781912mS PRN: WARNING:
1389781912mS PRN: 1389781912 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389781912mS PRN:
1389781913mS SPY: 1389781912 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389781937mS SIP Tx: UDP Internal LAN IP:5060 -> Customer's WAN IP:5060
SIP/2.0 200 Ok
Via: SIP/2.0/UDP Customer's WAN IP:5060;branch=z9hG4bK57a9.f728edf5.0
Via: SIP/2.0/UDP Other IP:5060;branch=z9hG4bK57a9.792b2627.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bce064d8c9eea6c79
Record-Route: <sip:+Customer's Main Number@Customer's WAN IP:5060;nat=yes;ftag=gK02292d1c;lr=on>
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29919 INVITE
Contact: "+Customer's Main Number" <sip:+Customer's Main Number@External IP:5060;transport=udp>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, INFO
Content-Type: application/sdp
Content-Length: 229

v=0
o=UserA 3086211473 4142208928 IN IP4 External IP
s=Session SDP
c=IN IP4 External IP
t=0 0
m=audio 49160 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
1389782151mS PRN: Form Fail Response
1389782207mS PRN: Form Fail Response
1389782250mS PRN: Form Fail Response
1389782306mS PRN: Form Fail Response
1389782369mS PRN: Form Fail Response
1389783071mS PRN: Form Fail Response
1389783102mS PRN: Form Fail Response
1389783883mS PRN: Form Fail Response
1389784646mS PRN: Form Fail Response
1389785411mS PRN: Form Fail Response
1389785599mS PRN: Form Fail Response
1389785937mS SIP Tx: UDP Internal LAN IP:5060 -> Customer's WAN IP:5060
SIP/2.0 200 Ok
Via: SIP/2.0/UDP Customer's WAN IP:5060;branch=z9hG4bK57a9.f728edf5.0
Via: SIP/2.0/UDP Other IP:5060;branch=z9hG4bK57a9.792b2627.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bce064d8c9eea6c79
Record-Route: <sip:+Customer's Main Number@Customer's WAN IP:5060;nat=yes;ftag=gK02292d1c;lr=on>
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29919 INVITE
Contact: "+Customer's Main Number" <sip:+Customer's Main Number@External IP:5060;transport=udp>
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, INFO
Content-Type: application/sdp
Content-Length: 229

v=0
o=UserA 3086211473 4142208928 IN IP4 External IP
s=Session SDP
c=IN IP4 External IP
t=0 0
m=audio 49160 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
1389786176mS PRN: Form Fail Response
1389786198mS RES: Fri 21/2/2014 12:24:47 FreeMem=70635740(1) CMMsg=5 (5) Buff=200 950 999 7470 5 Links=19092
1389786198mS RES2: IP 500 5.0(26) Tasks=31 RTEngine=0 CMRTEngine=0 Timer=46 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
1389786940mS PRN: Form Fail Response
1389787704mS PRN: Form Fail Response
1389789405mS PRN: Form Fail Response
1389789559mS PRN: Form Fail Response
1389789605mS PRN: Form Fail Response
1389789665mS SIP Rx: UDP Calling Party's WAN IP:5060 -> Internal LAN IP:5060
ACK sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bd5810c109eea6c79
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29919 ACK
Max-Forwards: 70
Content-Length: 0

1389789667mS SIP Rx: UDP Calling Party's WAN IP:5060 -> Internal LAN IP:5060
BYE sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bd5827d7a9eea6c79
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29920 BYE
Max-Forwards: 70
Content-Length: 0

1389789871mS PRN: Form Fail Response
1389790158mS SIP Rx: UDP Calling Party's WAN IP:5060 -> Internal LAN IP:5060
BYE sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bd5827d7a9eea6c79
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29920 BYE
Max-Forwards: 70
Content-Length: 0

1389790606mS PRN: Form Fail Response
1389791159mS SIP Rx: UDP Calling Party's WAN IP:5060 -> Internal LAN IP:5060
BYE sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bd5827d7a9eea6c79
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29920 BYE
Max-Forwards: 70
Content-Length: 0

1389791585mS PRN: Form Fail Response
1389791775mS PRN: Form Fail Response
1389792198mS RES: Fri 21/2/2014 12:24:53 FreeMem=70635148(1) CMMsg=5 (5) Buff=200 950 999 7470 5 Links=19093
1389792198mS RES2: IP 500 5.0(26) Tasks=31 RTEngine=0 CMRTEngine=0 Timer=46 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
1389793105mS PRN: Form Fail Response
1389793158mS SIP Rx: UDP Calling Party's WAN IP:5060 -> Internal LAN IP:5060
BYE sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK02Bd5827d7a9eea6c79
From: ""Name of Caller"" <sip:XXXXX@X.X.X.X:5060;isup-oli=62>;tag=gK02292d1c
To: <sip:+Customer's Main Number@Other IP:5060>;tag=78e604f5841834de
Call-ID: 1979893424_116604076@Calling Party's WAN IP
CSeq: 29920 BYE
Max-Forwards: 70
Content-Length: 0

1389793750mS PRN: Form Fail Response
1389794952mS PRN: WARNING:
1389794952mS PRN: 1389794952 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389794953mS PRN:
1389794953mS SPY: 1389794952 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389795829mS H323Evt: AudioEndPoint::Tick not present 30000 rx_ok 0 tx_ok 1 send_only 0 last_rx 0 last_tx 1389795825 last_icmp 0 start_icmp 0 start_operational 522191341
1389795829mS H323Evt: AudioEndPoint::Tick not present 30000 rx_ok 0 tx_ok 1 send_only 0 last_rx 0 last_tx 1389795820 last_icmp 0 start_icmp 0 start_operational 522196197
1389795829mS H323Evt: AudioEndPoint::Tick not present 30000 rx_ok 0 tx_ok 1 send_only 0 last_rx 0 last_tx 1389795825 last_icmp 0 start_icmp 0 start_operational 1228442177
1389796794mS PRN: Form Fail Response
1389796908mS PRN: Form Fail Response
1389796912mS PRN: WARNING:
1389796912mS PRN: 1389796912 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389796912mS PRN:
1389796912mS SPY: 1389796912 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389797377mS PRN: Form Fail Response
1389798109mS PRN: Form Fail Response
1389798268mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: TimerExpired cause=CMTCNoAnswerTimeout
1389798268mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: Retarget NOANSWER EXCEPTED=00000001 ValidTargets=1
1389798268mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: Retarget on target_cfg_user=Other Name
1389798268mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: ADD USER: Other Name depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeDefault) incl(0x1) excpt(0x1), allow_redir(0) remote=00000000
1389798269mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: SELECT: TRY VOICEMAIL orig_hg() orig_user(101)
1389798269mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: ADD VM TARGET
1389798269mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: ADD VM TARGET: FAILED availability=0
1389798270mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: VM targeting failed. Remaining on final target Other Name
1389798270mS CMTARGET: 18.22279.1 5469 SIPTrunk Endpoint: GetNoAnswerTimer:30
1389798577mS PRN: Form Fail Response
1389800606mS PRN: Form Fail Response
1389804878mS PRN: Form Fail Response
1389806079mS PRN: Form Fail Response
1389806647mS PRN: Form Fail Response
1389806814mS PRN: Form Fail Response
1389808297mS PRN: Form Fail Response
1389808627mS PRN: Form Fail Response
1389808791mS PRN: Form Fail Response
1389809061mS PRN: Form Fail Response
1389809825mS PRN: Form Fail Response
1389809952mS PRN: WARNING:
1389809952mS PRN: 1389809952 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389809952mS PRN:
1389809952mS SPY: 1389809952 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389810198mS RES: Fri 21/2/2014 12:25:11 FreeMem=70645188(1) CMMsg=5 (5) Buff=200 950 999 7470 5 Links=19096
1389810198mS RES2: IP 500 5.0(26) Tasks=31 RTEngine=0 CMRTEngine=0 Timer=45 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
1389810590mS PRN: Form Fail Response
1389811354mS PRN: Form Fail Response
1389811816mS PRN: Form Fail Response
1389811922mS PRN: WARNING:
1389811922mS PRN: 1389811922 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389811922mS PRN:
1389811922mS SPY: 1389811922 - CCU: 0, Called ccup_rtcp_report_status. status_type=0x8
1389812119mS PRN: Form Fail Response
1389812384mS PRN: Form Fail Response
1389812906mS PRN: Form Fail Response
1389813585mS PRN: Form Fail Response
1389813656mS PRN: Form Fail Response
1389814147mS PRN: Form Fail Response
1389814406mS PRN: Form Fail Response
1389815156mS PRN: Form Fail Response
1389815906mS PRN: Form Fail Response
1389816128mS PRN: Form Fail Response
1389816656mS PRN: Form Fail Response
1389818741mS PRN: Form Fail Response
1389818741mS PRN: Form Fail Response
1389818741mS PRN: Form Fail Response
1389819886mS PRN: Form Fail Response
1389821087mS PRN: Form Fail Response
1389821653mS PRN: Form Fail Response
1389821835mS PRN: Form Fail Response
1389823634mS PRN: Form Fail Response
1389823812mS PRN: Form Fail Response
1389824962mS PRN: WARNING:
1389824962mS PRN: 1389824962 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389824962mS PRN:
1389824962mS SPY: 1389824962 - CCU: 2, Called ccup_rtcp_report_status. status_type=0x8
1389826144mS SIP Rx: UDP Customer's WAN IP:5060 -> Internal LAN IP:5060
BYE sip:+Customer's Main Number@External IP:5060;transport=udp SIP/2.0
Record-Route: <sip:+Customer's Main Number@Customer's WAN IP:5060;nat=yes;ftag=gK0d018e19;lr=on>
Via: SIP/2.0/UDP Customer's WAN IP:5060;branch=z9hG4bKd7f4.1b05c8f4.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK0dB4b1078a7bcaee73d
From: ""Name of Caller"" <sip:CallerID@Calling Party's WAN IP:5060;isup-oli=62>;tag=gK0d018e19
To: <sip:+Customer's Main Number@Customer's WAN IP:5060>;tag=f6c2a42a5e1f8db0
Call-ID: 789431016_94586618@Calling Party's WAN IP
CSeq: 28820 BYE
Max-Forwards: 69
Supported: 100rel
Content-Length: 0

1389826147mS SIP Tx: UDP Internal LAN IP:5060 -> Customer's WAN IP:5060
SIP/2.0 200 Ok
Via: SIP/2.0/UDP Customer's WAN IP:5060;branch=z9hG4bKd7f4.1b05c8f4.0
Via: SIP/2.0/UDP Calling Party's WAN IP:5060;branch=z9hG4bK0dB4b1078a7bcaee73d
Record-Route: <sip:+Customer's Main Number@Customer's WAN IP:5060;nat=yes;ftag=gK0d018e19;lr=on>
From: ""Name of Caller"" <sip:CallerID@Calling Party's WAN IP:5060;isup-oli=62>;tag=gK0d018e19
To: <sip:+Customer's Main Number@Customer's WAN IP:5060>;tag=f6c2a42a5e1f8db0
Call-ID: 789431016_94586618@Calling Party's WAN IP
CSeq: 28820 BYE
Content-Length: 0

-------------------------------------------------------------------------------------

Minus the "PRN: Form Fail Response" that I've heard doesn't really hurt anything, I don't know what else seems off about this log.

I'm getting desperate, and the customer is looking to me for answers when I've already exhausted all my resources. I would appreciate any help you can give and I have 19 days worth of logs as well.

smokinjoe2938 · Feb 25, 2014

I would place a call immediately to your SIP provider for testing of the sip circuit

acss sme acis sme acss cm 5.2.1 acss cm and cmm acss aura messaging.

rpavlinich · Feb 25, 2014

The last time I called them to review this issue, they said that the only thing that could make this happen is if the PBX doesn't send a BYE and assured me that the SIP circuit is working as it should on their end. I don't know if this is a provider issue or an issue with this IPO.

mforrence · Feb 25, 2014

Fail form response" is something I see when we have a corrupt IPO config. Beware...

mforrence · Feb 25, 2014

Make that "Form Fail Response"...

redphone · Feb 25, 2014

From the log that you provided, IP Office never sends a 200 OK to the BYE (Call-ID: 1979893424_116604076). The BYE is received immediately (2ms) after the call has been established. This may be too fast for IPO to recognize (just a theory), as later in the log there is evidence that IPO can send a 200 OK to a BYE (Call-ID: 789431016_94586618). Because a BYE is sent by the service provider, I don't think they should have a large phone bill. As far as the SP is concerned, the call disconnected immediately. It is just a zombie call on the IP Office.

To prevent this, I would recommend changing the Auto Attendant to disconnect after playing through a few times rather than a simple continuous loop. That way IP Office will clear any zombie calls that may exist from a fast disconnect.

rpavlinich · Feb 25, 2014

Service provider said that the call was in fact disconnected on their end after about 1 min. So no service charges.

How would I get the AA to do what you're recommending? Maximum Inactivity is set to 8, is there any other way to tell the AA how to disconnect?

redphone · Feb 25, 2014

Just a couple examples (I am sure there are better ways):
Menu Timeout goes to another Menu with the same prompt and options, except the Timeout in this Menu goes to a Disconnect action. The menu is repeated once then disconnected if nothing is pressed.

Or add a DTMF digit in the first Menu to have the caller press to repeat the menu options and have the Timeout go to a Disconnect action. Caller must press a digit to repeat the menu or the call will be disconnected.

This is just a band-aid to the real problem; IPO is not acknowledging the BYE. You may want to look for known issues with R5.0 and SIP or correct a possible corrupt config.

rpavlinich · Feb 25, 2014

I have came up with a temporary band-aid:

How it was: ICR pointing to the HuntgroupA that ultimately forwards to the AA

My fix: I'm pointing the ICR at **1, which is Short Code DialExtn/[HuntgroupA's Extn #]t(240) so that all calls coming in will be disconnected after 4 hours.

amriddle01 · Feb 25, 2014

Get a cheap/free trial SIP trunk from another provider and try that, but I think 4 hours is a little long or do they frequently speak for 2/3 hours on one call?

rpavlinich · Feb 25, 2014

I would try a trial trunk, but this issue is very sporadic(as usual, I love when stuff doesn't happen when I'm there) sometimes happening twice in one day, then not happening again for 20 days.

The customer and I agreed on 2 hours instead of 4. 4 was indeed a bit excessive.

I also insisted that they upgrade to R8 for more SIP flexibilty and support and while the upgrade happens, I'd like to default the config and try to get rid of some of these error messages.

tlpeter · Feb 25, 2014

rpavlinich, i have had issues with embedded voicemail on 6.0 where the messages would be distorted and then voicemail channel was stuck.
this seems to happen to you.
What happened to me is that there was a call forwarded externally but the external party was busy (analog trunk)
The system then keeps trying to forward the call and the call became distorted and the VM channel was get stuck.
I know this was a bug in 5.0 too for sure but i cannot find it anymore.
Try to find out if you have the same problem.
There is a tool called system status which can tell you if your VM channels are in use or not.

BAZINGA!

I'm not insane, my mother had me tested!

rpavlinich · Feb 26, 2014

I swear, every problem I have with IPO is one of those one-off, little known issues that few people have dealt with.

Tlpeter, yes my VM channels were being hogged. It was through System Status that I actually had to manually disconnect the calls so people could access their VM again. But these calls were also using up SIP channels at the same time. Do you still think that I could be having the same issue you describe?

amriddle01 · Feb 26, 2014

I swear, every problem I have with IPO is one of those one-off, little known issues that few people have dealt with

There is one common factor though

rpavlinich · Feb 26, 2014

amriddle said:
There is one common factor though

That Nortel didn't have those issues? Jk. Yes, maybe it is me.

amriddle01 · Feb 26, 2014

Wait until it's upgraded, R5 is pretty old now and had bugs we can't even remember

tlpeter · Feb 26, 2014

I had it on 6.0.8 and it was gone after upgrading it to 6.0.14 but then they already invested in VMPro.

BAZINGA!

I'm not insane, my mother had me tested!

Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

Certain SIP calls hit Auto Attendant, then never disconnect Urgent

rpavlinich

ISP

smokinjoe2938

Programmer

rpavlinich

ISP

mforrence

Vendor

mforrence

Vendor

redphone

Programmer

rpavlinich

ISP

redphone

Programmer

rpavlinich

ISP

amriddle01

Programmer

rpavlinich

ISP

tlpeter

Programmer

rpavlinich

ISP

amriddle01

Programmer

rpavlinich

ISP

amriddle01

Programmer

tlpeter

Programmer

Similar threads

Part and Inventory Search

Sponsor

Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

Certain SIP calls hit Auto Attendant, then never disconnect *Urgent*

ISP

Programmer

ISP

Vendor

Vendor

Programmer

ISP

Programmer

ISP

Programmer

ISP

Programmer

ISP

Programmer

ISP

Programmer

Programmer

Similar threads

Log in

Part and Inventory Search

Sponsor

Certain SIP calls hit Auto Attendant, then never disconnect Urgent