SIP Trunk on IP Office - No voice when VM picks up 1

[tmcd123]

Customer running IPO 500 9.0.829. VM Pro 9.0.311. Using a Broadview SIP trunk. If we have the LAN 2 connected directly to our ISP static Public address, everything works 100% fine. We are trying to put a firewall in place between the public address and our LAN 2. We are able to make and receive calls but when a call goes to VM, there is no Voice. We have tried using a Cisco ASA 5510 and also tried a Cisco RV120. Both firewalls have the same issue. I'm assuming its a setting in the firewall but we cannot figure out what. He have disabled H323 inspect on the ASA and SIP Alg on the RV120. IP routes in IP Office have been changed accordingly.
Any thing else we should be looking at?

 

[AACon]

Do you have a two walk talk path between the users and sip trunk?
Do you have RTP keepalives enabled?

-Austin
ACE: Implement IP Office

 

[tmcd123]

Yes, two way talk path is good. RTP keepalives is enabled on LAN 2 in IP Office. It works no problem on straight Public IP to LAN 2.

 

[AACon]

Okay so...with the firewall in place, you *do* or *don't* get a two way talk path?
I guess I need more details on the symptoms when the firewall is in place.
IE when it's in place, you can call out and in no issue? Picking up, two way talk path?
However, if you call in and it goes to voicemail...what happens? No voicemail audio, or the voicemail system cannot hear you (like dtmf digits or doesn't record anything)?

-Austin
ACE: Implement IP Office

 

[tmcd123]

With the firewall in place, there is two way talk path. Calls sound fine. Call in/out with no issues and both parties can hear with no issues.
If you call in and it goes to VM, there is no VM audio. I can see it hitting the VM in system status but no greetings will play.

 

[AACon]

I've seen this before I think, and I'm pretty sure it's an authorization issue. Do you have any SIP traces?
If I remember correctly, it required an authorized phone number to be put in place under the SIP settings in Voicemail.

-Austin
ACE: Implement IP Office

 

[tmcd123]

Yes, monitor is running.
There is an authorized number in the Voicemail tab/SIP Settings. Again, it works when we are directly connected to a Public IP.

 

[AACon]

Oh yeah. Hm.....HMMMMmmmmm....HHhmmmm. You have the full RTP range open, as well as 5060 through the firewall yes?
Post a SIP trace of a call that goes to VM.

-Austin
ACE: Implement IP Office

 

[tmcd123]

Sorry, SIP traces were not turned on.

 

[bscolo]

Did you find a solution to this? Having the same problem.

 

[tmcd123]

We had to turn off SIP and H323 inspect inside the firewall. Worked greatest after they were both disabled.

 

[amriddle01]

They should always be turned off for SIP anyway, first thing we tell folks when we sell/recommend SIP trunks

 

[bscolo]

I don't know what it is but I disabled SIP ALG on our touter/firewall and it worked!

 

[tmcd123]

Yep, that one too. Glad to hear.

 

[Zandolee]

Yep, always turn off Sip ALG and packet inspection

 

[ncarter2]

I'm also having this problem, I've got an IP Office V2 at 9.0.3 with Voicemail Pro. Sip trunks from FlowRoute which work perfectly inbound and outbound when answered by a person. But any call that goes to VM, or that rings into an Auto Attendant just gives me dead air and then drops. In SSA im able to see the call ring and it says its connected to the Voicemail module. although, from inside the Voicemail Pro Client it does not register any "Active Voicemail Session".

Voicemail seems to work properly from inside, in fact if I call in and get answered and then get transferred to VM/AA it works correctly

I've checked the firewall SIP ALG/Inspections and they are all off. IF someone understands Monitor Traces and could tell me what trace options would be useful I'd be happy to supply them...

 

[AACon]

Thats funny. I had the same problem the other day, but then it went away after a few hours, with no changes on my side.

-Austin
ACE: Implement IP Office

 

[ncarter2]

Just tried switching to Embedded VM, it reacts the same way...

 

[AACon]

Turn on verbose sip traces, and upload the monitor trace.

-Austin
ACE: Implement IP Office

 

[ncarter2]

********** SysMonitor v9.0.3.0 build 941 [connected to 192.168.1.53 (Wolf Electric)] **********
16:58:40 2711046mS PRN: Monitor Status IP 500 V2 9.0.3.0 build 941
16:58:40 2711046mS PRN: LAW=U PRI=0, BRI=0, ALOG=4, VCOMP=10, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=0 VMAIL=1(VER=2 TYP=3) 1-X=1 CALLS=0(TOT=7)
16:58:40 2711552mS PRN: Optimizing BTree Lists Completed...Started:2711413
16:58:41 2712929mS SIP Rx: UDP 70.167.153.130:5060 -> 192.168.1.53:5060
OPTIONS sip:50.193.48.120:5060 SIP/2.0
Max-Forwards: 10
Record-Route: <sip:70.167.153.130;lr>
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKf8ce.b6a8564870ff61711a90dbfc11b80ba5.0
Via: SIP/2.0/UDP 70.167.153.136:5060;branch=0
Route: <sip:70.167.153.130;lr;received='sip:50.193.48.120:5060'>
From: siping@invalid;tag=b416eaf9
To: sip:50.193.48.120:5060
Call-ID: 0c26e475-1b391ff8-8773c68@70.167.153.136
CSeq: 1 OPTIONS
Content-Length: 0

16:58:41 2712931mS Sip: Association found trunk: SIP Line (17)
16:58:41 2712931mS Sip: SIPDialog f4eba218 created, dialogs 1
16:58:41 2712931mS Sip: (f4eba218) ExtractContactFromMessage: cannot get Contact Header 2012
16:58:41 2712932mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent_by: 70.167.153.130 trunk
16:58:41 2712932mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent by transport: SIP/2.0/UDP trunk
16:58:41 2712933mS Sip: (f4eba218) SendSIPResponse: OPTIONS code 200 SENT TO 70.167.153.130 5060
16:58:41 2712934mS SIP Tx: UDP 192.168.1.53:5060 -> 70.167.153.130:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKf8ce.b6a8564870ff61711a90dbfc11b80ba5.0
Via: SIP/2.0/UDP 70.167.153.136:5060;branch=0
Record-Route: <sip:70.167.153.130;lr>
From: <siping@invalid>;tag=b416eaf9
Call-ID: 0c26e475-1b391ff8-8773c68@70.167.153.136
CSeq: 1 OPTIONS
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer
Server: IP Office 9.0.3.0 build 941
To: <sip:50.193.48.120:5060>;tag=816ec22ca8416014
Content-Type: application/sdp
Content-Length: 239

v=0
o=UserA 3738505294 2495882347 IN IP4 50.193.48.120
s=Session SDP
c=IN IP4 0.0.0.0
t=0 0
m=audio 8000 RTP/AVP 0 8 18 4
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/16000
16:58:41 2712934mS Sip: (f4eba218) UpdateSIPCallState SIPDialog::INITIAL(0) -> SIPDialog::FINAL(28)
16:58:43 2714896mS SIP Rx: UDP 70.167.153.130:5060 -> 192.168.1.53:5060
INVITE sip:14087276666@50.193.48.120:5060 SIP/2.0
Record-Route: <sip:70.167.153.130;lr>
Max-Forwards: 66
Record-Route: <sip:216.115.69.132;lr>
To: <sip:+14087276666@fl.gg>
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
Via: SIP/2.0/UDP 216.115.69.131;branch=z9hG4bKfeda.57897ef074dc8f7288a40b1a3b6e625f.1
Via: SIP/2.0/UDP 216.115.69.132;branch=z9hG4bKfeda.2d22d44a1ad628412a0d16dbf9a9bfe1.0
Via: SIP/2.0/UDP 4.55.17.35:5060;branch=z9hG4bK0cB5b291be563ad6ee9
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 INVITE
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay, multipart/mixed
Contact: <sip:+18018385555@4.55.17.35:5060>
Content-Length: 212
Content-Type: application/sdp
P-Asserted-Identity: <sip:+18018385555@fl.gg>

v=0
o=- 587 13035 IN IP4 4.55.17.2
s=-
c=IN IP4 4.55.17.2
t=0 0
m=audio 10096 RTP/AVP 0 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:20
16:58:43 2714900mS Sip: Association found trunk: SIP Line (17)
16:58:43 2714901mS CMCallEvt: 0.1049.0 -1 BaseEP: NEW CMEndpoint f4ec1a38 TOTAL NOW=1 CALL_LIST=0
16:58:43 2714901mS Sip: SIPDialog f4ec0438 created, dialogs 2
16:58:43 2714902mS Sip: License, Valid 1, Available 6, Consumed 0
16:58:43 2714902mS Sip: CheckLineMonitors on SIP Endpoint - KEY & LAMP for SIP Trunk!
16:58:43 2714902mS Sip: SIPTrunkEndpointDialogOwner::SetRemoteAddressForRequest from 70.167.153.130 to 4.55.17.35 not supported
16:58:43 2714903mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) Cloned
16:58:43 2714904mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent_by: 70.167.153.130 trunk
16:58:43 2714904mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent by transport: SIP/2.0/UDP trunk
16:58:43 2714904mS Sip: SIPTrunkEndpointDialogOwner::SetRemoteAddressForResponse from 70.167.153.130:5060 to 70.167.153.130:5060
16:58:43 2714904mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SendSIPResponse: INVITE code 100 SENT TO 70.167.153.130 5060
16:58:43 2714905mS SIP Tx: UDP 192.168.1.53:5060 -> 70.167.153.130:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
Via: SIP/2.0/UDP 216.115.69.131;branch=z9hG4bKfeda.57897ef074dc8f7288a40b1a3b6e625f.1
Via: SIP/2.0/UDP 216.115.69.132;branch=z9hG4bKfeda.2d22d44a1ad628412a0d16dbf9a9bfe1.0
Via: SIP/2.0/UDP 4.55.17.35:5060;branch=z9hG4bK0cB5b291be563ad6ee9
Record-Route: <sip:70.167.153.130;lr>
Record-Route: <sip:216.115.69.132;lr>
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 INVITE
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer
Server: IP Office 9.0.3.0 build 941
To: <sip:+14087276666@fl.gg>;tag=0b30422c5e5290d7
Content-Length: 0

16:58:43 2714905mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) INVITE Received ep 17.1049.1 -1 SIPTrunk Endpoint(f4ec1a38), dialog f4ec0438
16:58:43 2714906mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) LR is On and route is Route: <sip:70.167.153.130;lr>
16:58:43 2714906mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) LR is On and route is Route: <sip:216.115.69.132;lr>
16:58:43 2714906mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) UpdateSIPCallState SIPDialog::INITIAL(0) -> SIPDialog::INVITE_RCVD(9)
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) UpdateSDPState SIPDialog::IDLE(0) -> SIPDialog::OFFER_RCVD(2)
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SdpClone
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SIPDialog::BuildFastStartFromSDPOffer sdpmsg f4eb1d80
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SIPDialog::FindConnectionParameters: found media proto <RTP/AVP>
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SetRfc2833TxPayload: use RFC2833 for dtmf
16:58:43 2714907mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SIPDialog::BuildFastStartFromAudioMediaSDPOffer reinvite 0 msg f4e80838 fs in msg 1 mRTP_PType 255
16:58:43 2714908mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) SetRemoteRTPAddress to 4.55.17.2:10096
16:58:43 2714908mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) Process SIP request dialog f4ec0438, method INVITE in state SIPDialog::INVITE_RCVD(9)
16:58:43 2714909mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) UpdateClone mMesg f4ec0378 smsg f4e5d900
16:58:43 2714909mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) CMSetup forwarded to call model owner_ep 17.1049.1 -1 SIPTrunk Endpoint(f4ec1a38), dialog f4ec0438 has sdp 1
16:58:43 2714910mS CMCallEvt: CREATE CALL:8 (f4eb5690)
16:58:43 2714910mS CMCallEvt: 0.1050.0 -1 BaseEP: NEW CMEndpoint f4ea1d68 TOTAL NOW=2 CALL_LIST=0
16:58:43 2714913mS CMLineRx: v=0
CMSetup
Line: type=SIPLine 17 Call: lid=17 id=1049 in=1
Called[14087276666] Type=Default (100) Reason=CMDRdirect SndComp Calling[18018385555@fl.gg] Type=International Plan=Unknown
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 4 item(s)
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:1 N:0 R:4) number=18018385555@fl.gg
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x0 rx_gain=32 tx_gain=32 ep_callid=1049 ipaddr=192.168.1.53 apps=0 loc=999 em_loc=999 features2=0x0
16:58:43 2714913mS CD: CALL: 17.1049.1 BState=Idle Cut=1 Music=0.0 Aend="Line 17" (0.0) Bend="" [] (0.0) CalledNum=14087276666 () CallingNum=18018385555@fl.gg () Internal=0 Time=3 AState=Idle
16:58:43 2714913mS CMCallEvt: 17.1049.1 8 SIPTrunk Endpoint: StateChange: END=A CMCSIdle->CMCSDialInitiated
16:58:43 2714913mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: LOOKUP CALL ROUTE: type=100 called_party=14087276666 sub= calling=18018385555@fl.gg dir=in complete=1 ses=0
16:58:43 2714913mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: SET BESTMATCH: length 0 vs -1 match= dest=Main
16:58:43 2714913mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: SET BESTMATCH: length 10 vs 0 match=4087276666 dest=AA:Recordings
16:58:43 2714913mS CMCallEvt: Priority hike: call 8 priority 0->1
16:58:43 2714913mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: LOOKUP ICR: DDI=14087276666 CGPN=18018385555@fl.gg (Destination AA:Recordings ) => CDPN=AA:Recordings
16:58:43 2714914mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: ADD TARGET (N): number=AA:Recordings type=100 depth=1 nobar=1 setorig=1 ses=0
16:58:43 2714914mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: ADD VM TARGET
16:58:43 2714914mS CMTARGET: **** 17.1049.1 8 SIPTrunk Endpoint: MakeVoicemailTarget pbx=<null> local=1 type=3
16:58:43 2714915mS CMMap: a=0.18 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 1, total 10
16:58:43 2714915mS CMCallEvt: 0.1051.0 -1 BaseEP: NEW CMEndpoint f4e86e20 TOTAL NOW=3 CALL_LIST=1
16:58:43 2714915mS CMTARGET: 0.1051.0 8 RAS.0: ADD PRIMARY
16:58:43 2714915mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: ADD VM TARGET: SUCCEEDED
16:58:43 2714916mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: INITIAL TARGETING SUCCEEDED
16:58:43 2714916mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: GetNoAnswerTimer:15
16:58:43 2714916mS CMCallEvt: 17.1049.1 8 SIPTrunk Endpoint: StateChange: END=A CMCSDialInitiated->CMCSDialled
16:58:43 2714917mS CMLineTx: v=0
CMProceeding
Line: type=SIPLine 17 Call: lid=17 id=1049 in=1
16:58:43 2714918mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) received CMProceeding
16:58:43 2714918mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) SIPEndPoint: Received an CMProceeding State Transition to SIPDialog::INVITE_RCVD(9)
16:58:43 2714918mS CMCallEvt: 0.1050.0 8 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
16:58:43 2714919mS CMCallEvt: 0.1051.0 8 RAS.0: StateChange: END=T CMCSIdle->CMCSOffering
16:58:43 2714919mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 0->1051 )
16:58:43 2714919mS CMExtnTx: v=RAS, p1=0
CMSetup
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[#AA:Recordings] Type=Voicemail (102) Reason=CMDRX_Attendant SndComp Calling[18018385555@fl.gg] Type=International Plan=Unknown
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=21 chan=42
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:1 N:0 R:4) number=18018385555@fl.gg
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1049 ipaddr=192.168.1.53 apps=0 loc=999 em_loc=999 features2=0x0
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=14087276666
IE CMIEMohSourceId (247) MOH Source = 1
Display [18018385555>#AA:Recordings]
Timed: 24/09/14 16:58
Locale: enu
16:58:43 2714919mS CMMap: a=21.42 b=1.65534 T
16:58:43 2714924mS CMExtnRx: v=RAS, p1=0
CMConnect
Line: type=RAS 1 Call: lid=0 id=1011 in=0
16:58:43 2714924mS CMCallEvt: 0.1051.0 8 RAS.0: StateChange: END=T CMCSOffering->CMCSConnReq
16:58:43 2714924mS CMCallEvt: 0.1050.0 8 TargetingEP: RequestEnd 0.1051.0 8 RAS.0
16:58:43 2714924mS CMTARGET: 17.1049.1 8 SIPTrunk Endpoint: CancelTimer CMTCNoAnswerTimeout
16:58:43 2714924mS CMCallEvt: 0.1050.0 -1 BaseEP: DELETE CMEndpoint f4ea1d68 TOTAL NOW=2 CALL_LIST=1
16:58:43 2714925mS CMExtnEvt: v=1011 State, new=Connected old=Idle,0,0,RAS
16:58:43 2714925mS CMCallEvt: 17.1049.1 8 SIPTrunk Endpoint: StateChange: END=A CMCSDialled->CMCSOGConnReq
16:58:43 2714929mS CMLineTx: v=0
CMFacility
Line: type=SIPLine 17 Call: lid=17 id=1049 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
16:58:43 2714930mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) adding message CMFacility(f4e6b268) to nat message queue, size is 1
16:58:43 2714930mS CMLineTx: v=0
CMConnect
Line: type=SIPLine 17 Call: lid=17 id=1049 in=1
BChan: slot=21 chan=42
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
ConnectedName.Invoke.CodePageISO8859-1
invokeId 14631
user '#AA:Recordings' presentation Allowed
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=#AA:Recordings
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=#AA:Recordings
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceVoicemail type=0 number=0 channel=42 features=0x0 rx_gain=32 tx_gain=32 ep_callid=1051 ipaddr=192.168.1.53 apps=0 loc=0 em_loc=0 features2=0x0
16:58:43 2714931mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) adding message CMConnect(f56361a8) to nat message queue, size is 2
16:58:43 2714932mS CD: CALL: 17.1049.1 BState=Connected Cut=3 Music=0.0 Aend="Line 17" (0.0) Bend="#AA:Recordings(#AA:Recordings)" [VoiceMail] (21.42) CalledNum=#AA:Recordings () CallingNum=18018385555@fl.gg () Internal=0 Time=22 AState=Connected
16:58:43 2714934mS H323Evt: SetOperational 12 192.168.1.53:0 to 0
16:58:43 2714934mS H323Evt: SetRfc2833 12: (1) rx payload 101 tx payload 101
16:58:43 2714935mS CMMap: PCG::MapBChan pcp[85]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
16:58:43 2714935mS CMMap: PCGS CPReserveCodec for the other end (pcp[85]b0r1) true
16:58:43 2714935mS CMMap: PCG::MapBChan pcp[22]b1r0 cp_b f56681e0 other_cp_b f5670be0 type CGTypeSimple
16:58:43 2714935mS CMMap: a=0.18 b=21.42 M12
16:58:43 2714935mS CMMap: PlatformConnectionAudioSAP::Bind pcp[85]b0r1 to 0.18
16:58:43 2714935mS CMMap: PlatformConnectionAudioSAP::ConnectVoice (connect) pcp[85]b0r1 echo_cancellation set to 0
16:58:43 2714935mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[85]b0r1 Configure 0.18
16:58:43 2714935mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Open got rtpRelay ID: 1
16:58:43 2714936mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Configure success
16:58:43 2714936mS CMMap: PlatformConnectionAudioSAP::ConnectVoice local IP addr 192.168.1.53:49152, Remote IP addr 4.55.17.2:10096
16:58:43 2714936mS CMMap: PlatformConnectionAudioSAP::ConnectVoice DSP IP addr 1.1.1.3:32768, telogyHost IP addr 1.1.1.1:10
16:58:43 2714936mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Start success
16:58:43 2714936mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[85]b0r1 ConnectIndication 0.18
16:58:43 2714936mS H323Evt: SetOperational 12 192.168.1.53:49152 to 1
16:58:44 2715023mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) StunResolved ok 1 for msg f4e6b268, nat message queue size is 2
16:58:44 2715023mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) received CMFacility
16:58:44 2715023mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) SIPDialog cannot reshuffle in SIPDialog::INVITE_RCVD, CMFacilityInterval 0, PendingUpdateResp 0, has_fs 1, has_video 0, hold_changed, 0 name_changed 0 empty_reinvite 0
16:58:44 2715024mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec1a38) Finish StunResolved, nat message queue size is 1
16:58:44 2715138mS RES: Wed 24/9/2014 16:58:43 FreeMem=54772328 54333024(2) CachedMem=439304 CMMsg=3(6) Buff=5200 1371 999 7444 5 Links=6878 BTree=14697 CPU=11.90% CPUStats=26/29/8862/17297/20427/0/0 MCR=0 MCW=0
16:58:44 2715138mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=51 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=71 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=30(TLS=4) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
16:58:44 2715138mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
16:58:46 2717934mS Sip: sip_indicateTimeOut Timer 10
16:58:46 2717934mS Sip: Timer 10 callback found dialog f4eba218 0c26e475-1b391ff8-8773c68@70.167.153.136 OPTIONS SIPDialog::FINAL
16:58:46 2717934mS Sip: Completed f4eba218 ... removing Dialog of CallId 0c26e475-1b391ff8-8773c68@70.167.153.136 and State: SIPDialog::FINAL(28)
16:58:46 2717934mS Sip: SIPDialog f4eba218 deleted, dialogs 1
16:58:49 2720639mS RES: Wed 24/9/2014 16:58:49 FreeMem=54821152 54365832(3) CachedMem=455320 CMMsg=3(6) Buff=5200 1371 999 7443 5 Links=6881 BTree=14697 CPU=05.54% CPUStats=1/3/8862/19840/20427/0/0 MCR=0 MCW=0
16:58:49 2720640mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=51 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=68 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=30(TLS=4) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
16:58:49 2720640mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
16:58:55 2726477mS SIP Rx: UDP 70.167.153.130:5060 -> 192.168.1.53:5060
CANCEL sip:14087276666@50.193.48.120:5060 SIP/2.0
Max-Forwards: 66
To: <sip:+14087276666@fl.gg>
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 CANCEL
Content-Length: 0

16:58:55 2726478mS Sip: Find End Point2 17.1049.1 8 SIPTrunk Endpoint (f4ec1a38) Sip CallId 1678512083_132396@4.55.17.35
16:58:55 2726479mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) Process SIP request dialog f4ec0438, method CANCEL in state SIPDialog::INVITE_RCVD(9)
16:58:55 2726479mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent_by: 70.167.153.130 trunk
16:58:55 2726479mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent by transport: SIP/2.0/UDP trunk
16:58:55 2726479mS Sip: SIPTrunkEndpointDialogOwner::SetRemoteAddressForResponse from 70.167.153.130:5060 to 70.167.153.130:5060
16:58:55 2726480mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) SendSIPResponse: CANCEL code 200 SENT TO 70.167.153.130 5060
16:58:55 2726480mS SIP Tx: UDP 192.168.1.53:5060 -> 70.167.153.130:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 CANCEL
Supported: timer
Server: IP Office 9.0.3.0 build 941
To: <sip:+14087276666@fl.gg>;tag=0b30422c5e5290d7
Content-Length: 0

16:58:55 2726480mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent_by: 70.167.153.130 trunk
16:58:55 2726481mS Sip: SIPDialog::ExtractResponseParamsFromViaHeader remote sent by transport: SIP/2.0/UDP trunk
16:58:55 2726481mS Sip: SIPTrunkEndpointDialogOwner::SetRemoteAddressForResponse from 70.167.153.130:5060 to 70.167.153.130:5060
16:58:55 2726481mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) SendSIPResponse: INVITE code 487 SENT TO 70.167.153.130 5060
16:58:55 2726482mS SIP Tx: UDP 192.168.1.53:5060 -> 70.167.153.130:5060
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
Via: SIP/2.0/UDP 216.115.69.131;branch=z9hG4bKfeda.57897ef074dc8f7288a40b1a3b6e625f.1
Via: SIP/2.0/UDP 216.115.69.132;branch=z9hG4bKfeda.2d22d44a1ad628412a0d16dbf9a9bfe1.0
Via: SIP/2.0/UDP 4.55.17.35:5060;branch=z9hG4bK0cB5b291be563ad6ee9
Record-Route: <sip:70.167.153.130;lr>
Record-Route: <sip:216.115.69.132;lr>
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 INVITE
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY,UPDATE
Supported: timer
Server: IP Office 9.0.3.0 build 941
To: <sip:+14087276666@fl.gg>;tag=0b30422c5e5290d7
Content-Length: 0

16:58:55 2726483mS Sip: 17.1049.1 8 SIPTrunk Endpoint(f4ec0438) UpdateSIPCallState SIPDialog::INVITE_RCVD(9) -> SIPDialog::FINAL(28)
16:58:55 2726483mS CMLineRx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=1049 in=1
Called[] Type=Default (100) Reason=CMDRdirect Calling[18018385555@fl.gg] Type=International Plan=Unknown
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:1 N:0 R:4) number=18018385555@fl.gg
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=1049 ipaddr=192.168.1.53 apps=0 loc=999 em_loc=999 features2=0x0
Cause=16, Normal call clearing
16:58:55 2726483mS CMCallEvt: 17.1049.1 8 SIPTrunk Endpoint: StateChange: END=A CMCSOGConnReq->CMCSCompleted
16:58:55 2726486mS CMLOGGING: CALL:2014/09/2416:58,00:00:00,000,18018385555@fl.gg,I,#AA:Recordings,14087276666,,,,0,,""n/a,0
16:58:55 2726486mS CD: CALL: 17.1049.1 BState=Connected Cut=2 Music=0.0 Aend="L#AA:Recordings(#AA:Recordings)" (0.0) Bend="#AA:Recordings(#AA:Recordings)" [VoiceMail] (21.42) CalledNum=#AA:Recordings () CallingNum=18018385555@fl.gg () Internal=0 Time=
11576 AState=Idle
16:58:55 2726486mS CD: CALL: 17.1049.1 Deleted
16:58:55 2726486mS Sip: 17.1049.1 -1 SIPTrunk Endpoint(f4ec0438) KeepDlgOnCmCallLost SIPDialog::FINAL
16:58:55 2726486mS Sip: SIPDialog f4ec0438 deleted, dialogs 0
16:58:55 2726487mS CMCallEvt: 17.1049.1 -1 SIPTrunk Endpoint: StateChange: END=X CMCSCompleted->CMCSDelete
16:58:55 2726487mS CMExtnEvt: RAS: CALL LOST (CMCauseNormal)
16:58:55 2726488mS CMCallEvt: 0.1051.0 -1 RAS.0: StateChange: END=X CMCSConnReq->CMCSCompleted
16:58:55 2726488mS CMExtnEvt: v=1011 State, new=PortRecoverDelay old=Connected,0,0,RAS
16:58:55 2726488mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[#AA:Recordings] Type=Voicemail (102) Reason=CMDRX_Attendant Calling[18018385555@fl.gg] Type=International Plan=Unknown
BChan: slot=21 chan=42
Cause=16, Normal call clearing
16:58:55 2726488mS CMMap: a=21.42 b=0.0 T0
16:58:55 2726489mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 1051->0 )
16:58:55 2726489mS CMCallEvt: 0.1051.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
16:58:55 2726489mS CMExtnEvt: v=1011 State, new=Idle old=PortRecoverDelay,0,0,RAS
16:58:55 2726489mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
BChan: slot=21 chan=42
Cause=16, Normal call clearing
16:58:55 2726490mS CMCallEvt: 0.1051.0 -1 BaseEP: DELETE CMEndpoint f4e86e20 TOTAL NOW=1 CALL_LIST=0
16:58:55 2726490mS CMCallEvt: END CALL:8 (f4eb5690)
16:58:55 2726491mS Sip: ~SipTrunkEndpoint 17.1049.1 -1 SIPTrunk Endpoint
16:58:55 2726492mS CMTARGET: 17.1049.1 -1 BaseEP: ~CMTargetHandler f4ea71f0 ep f4ec1a38
16:58:55 2726492mS CMCallEvt: 17.1049.1 -1 BaseEP: DELETE CMEndpoint f4ec1a38 TOTAL NOW=0 CALL_LIST=0
16:58:55 2726494mS CMMap: PCG::UnmapBChan pcp[22]b1r0 cp_b f56681e0 other_cp_b f5670be0
16:58:55 2726495mS CMMap: a=0.18 b=21.42 M02
16:58:55 2726495mS CMMap: PlatformConnectionAudioSAP:isconnectVoice rtpRelay ID: 1 Close success
16:58:55 2726495mS H323Evt: SetOperational 12 192.168.1.53:49152 to 0
16:58:55 2726495mS CMMap: PCG::UnmapBChan pcp[85]b0r1 cp_b 0 other_cp_b 0
16:58:55 2726496mS H323Evt: RTP(END): 192.168.1.53/49152 4.55.17.2/10096 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=on AGE=11561 SENT=567 RECV=11 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
16:58:55 2726497mS CMMap: a=0.18 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 1, total 10
16:58:55 2726511mS SIP Rx: UDP 70.167.153.130:5060 -> 192.168.1.53:5060
ACK sip:14087276666@50.193.48.120:5060 SIP/2.0
Max-Forwards: 66
To: <sip:+14087276666@fl.gg>;tag=0b30422c5e5290d7
From: <sip:+18018385555@fl.gg>;tag=gK0c141a38
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bKfeda.b718ac53dc02724ad0d265e959ca884f.0
Call-ID: 1678512083_132396@4.55.17.35
CSeq: 7043 ACK
Content-Length: 0

16:58:55 2726512mS Sip: Association found trunk: SIP Line (17)
16:58:55 2726640mS RES: Wed 24/9/2014 16:58:55 FreeMem=54878256 54333024(3) CachedMem=545232 CMMsg=5(6) Buff=5200 1371 999 7444 5 Links=6992 BTree=14698 CPU=05.84% CPUStats=1/3/8862/19817/20427/0/0 MCR=0 MCW=0
16:58:55 2726640mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=51 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=68 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=30(TLS=4) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
16:58:55 2726640mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)

********** Warning: Logging to Screen Stopped **********