We are a public school district and have an 18-month-old Lync 2010 server deployment with an AudioCodes Mediant 1000 gateway and a PRI from TDS Telecom. We are very happy with Lync for Voice and this is the first major issue - I don't have formal Lync training and of course the original services contract was closed out by the time we identified this as a pattern. 

Problem: I am looking for some basic troubleshooting steps for this issue: we are unable to dial outgoing 877 and 866 numbers (most 800 and 888 numbers are ok). The error received at the handset is a fast busy signal and "Call unsuccessful. Calling service or server is temporarily unavailable." The software client references error ID 500 (source ID 241).

Steps we have taken:

1. Verified with telco that 877/866 are not blocked on their side. Tested from one of our emergency phones (POTS from same telco) and we are able to make the call there.
2. Filed a support request in with AudioCodes (current).
3. Lync Report Server - see below.

More info: in the Report Server, I can see this detail:

Diagnostic Report

Report time: 3/10/2014 1:53:44 PM         Response code: 500 Diagnostic ID: 10500     Request type: INVITE Content type: multipart/alternative     Source: acsLync1.alton.school.com Application: MediationServer     From user URI: pmcleod@alton.k12.... To user URI: 18773526710;phone-context=DefaultProfile     From user agent: CPE/4.0.7577.4100 OCPhone/4.0.7577.4100 (Microsoft Lync 2010 Phone Edition)     Diagnostic header: 10500; source="acsLync1.alton.school.com"; reason="Gateway responded with 500 Server Internal Error"; component="MediationServer"; SipResponseCode="500"; SipResponseText="Server Internal Error"; sip-reason="Q.850 ; cause=111"; GatewayFqdn="10.5.0.98"      Additional diagnostic information   Seq # Diagnostic ID Source Application Diagnostic Header   1 12006 acsLync1.alton.school.com OutboundRouting 12006; reason="Trying next hop"; source="acsLync1.alton.school.com"; PhoneUsage="Long Distance"; PhoneRoute="Long Distance"; Gateway="10.5.0.98"; appName="OutboundRouting"

Report time:		3/10/2014 1:53:44 PM
	Response code:		500		Diagnostic ID:	10500
	Request type:		INVITE		Content type:	multipart/alternative
	Source:				Application:	MediationServer
	From user URI:		pmcleod@alton...		To user URI:	+18773526710@alton.k12...
	From user agent:		CPE/4.0.7577.4100 OCPhone/4.0.7577.4100 (Microsoft Lync 2010 Phone Edition)
	Diagnostic header:		10500; reason="Gateway responded with 500 Server Internal Error"; component="MediationServer"; SipResponseCode="500"; SipResponseText="Server Internal Error"; sip-reason="Q.850 ; cause=111"; OriginalPresenceState="0"; CurrentPresenceState="0"; MeInsideUser="Yes"; ConversationInitiatedBy="0"; SourceNetwork="0"; RemotePartyCanDoIM="No"
	Additional diagnostic information
	Seq #	Diagnostic ID	Source	Application	Diagnostic Header
	1	12006	acsLync1.alton.school.com	OutboundRouting	12006; reason="Trying next hop"; source="acsLync1.alton.school.com"; PhoneUsage="Long Distance"; PhoneRoute="Long Distance"; Gateway="10.5.0.98"; appName="OutboundRouting"

• Edited by pmcleod Monday, March 10, 2014 6:30 PM

You have to run logs on your gateway. What do you use? AudioCodes or some other device?

That may be your NPI/TON settings on the gateway.  Pick a couple of broken numbers, create a manipulation rule so that the number appears as if NPI=E.164Public, TON=National.  If this is an AudioCodes, you'll see it in there. 

If that eases your issue, you can probably set it for all toll free calls.

Thanks, you both tend to think it's the gateway, so that's helpful. Waiting for a call back from Audiocodes and we'll see if they can help!

Please update when you get the results, my money is on NPI/TON, this is an easy fix.  Occasionally, early media, but I bet this is NPI/TON.  :)

Here's an update from the Audiocodes session - Audiocodes says it's clearly on the pstn side:

(   lgr_psbrdex)(6503687   )  pstn recv <-- CALL_DISCONNECTED Trunk:0 Conn:0 RetCause:104 NetCause:111 [Time: 15:16:12]
(   lgr_psbrdif)(6503688   )  Abnormal Disconnect cause:111#GWAPP_PROTOCOL_ERROR_UNSPECIFIED Trunk:0 Conn:0 [Time: 15:16:12]
(      lgr_flow)(6503689   )  #52:LOCAL_CALL_DISCONNECTED_EV(Trunk:0 Conn:0 Bchannel:23 TpEv=67) [Time: 15:16:12]
(      lgr_flow)(6503690   )  |       #52:LOCAL_CALL_DISCONNECTED_EV [Time: 15:16:12]
(      lgr_flow)(6503691   )  |       #52:Close voice Channel [Time: 15:16:12]

Which could be interesting. We are rural and this is the first PRI installed in our region; and as I mentioned before, I can dial the number fine from our emergency phones or from my phone at home, which are from the same telco. I've pasted in the full Audiocodes log below (I x'd out my own number).

I really appreciate everyone's help!

(      lgr_flow)(6503587   )  ListeningTcpTransportObject#0- CTcpSocket::HandleSocketEvent socket connected [Time: 15:16:11]
(      lgr_flow)(6503588   )  ListeningTcpTransportObject#0- CTcpServerSocket::IsSocketPending socket is pending for accept [Time: 15:16:11]
(     sip_stack)(6503589   )  new TcpTransportObject created - #376 [Time: 15:16:11]
(     sip_stack)(6503590   )  New Socket buffer allocated - #140 [Time: 15:16:11]
(     sip_stack)(6503591   )  New SIPMessage created - #166 [Time: 15:16:11]
(      lgr_flow)(6503592   )  ---- Incoming SIP Message from 10.5.0.96:56057 to SIPInterface #0 ---- [Time: 15:16:11]
INVITE sip:18773526710@10.5.0.98;user=phone SIP/2.0
FROM: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
TO: <sip:18773526710@10.5.0.98;user=phone>
CSEQ: 16403 INVITE
CALL-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK3f1494f2
CONTACT: <sip:acsLync1.alton.school.com:5060;transport=Tcp;maddr=10.5.0.96;ms-opaque=85fe2b1fcf302a40>
CONTENT-LENGTH: 332
SUPPORTED: 100rel
USER-AGENT: RTCC/4.0.0.0 MediationServer
CONTENT-TYPE: application/sdp
ALLOW: ACK
Allow: CANCEL,BYE,INVITE,PRACK,UPDATE
v=0
o=- 1767 1 IN IP4 10.5.0.96
s=session
c=IN IP4 10.5.0.96
b=CT:1000
t=0 0
m=audio 55720 RTP/AVP 97 101 13 0 8
c=IN IP4 10.5.0.96
a=rtcp:55721
a=label:Audio
a=sendrecv
a=rtpmap:97 RED/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=ptime:20
 [Time: 15:16:11]
(     sip_stack)(6503594   )  new AcSIPCallAPI created - #20 [Time: 15:16:11]
(      lgr_flow)(6503595   )  |       | new GetNewSIPCall created - #480 [Time: 15:16:11]
(  lgr_stk_mngr)(6503596   )  Resource StackSession <#471> Allocated [Time: 15:16:11]
(     sip_stack)(6503597   )  TcpTransportObject#376::CheckForConnectionPersistent - Opening persistent connection with proxy: 10.5.0.96:56057 [Time: 15:16:11]
(      lgr_flow)(6503598   )  |       |(SIPTU#480)INVITE State:Idle() [Time: 15:16:11]
(     sip_stack)(6503599   )  SIPCall(#480) changes state from Idle to Invited [Time: 15:16:11]
(      lgr_flow)(6503600   )  |       |       |       #471:SIP_SETUP_EV(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_call)(6503601   )  (#5) Call Allocated. [Time: 15:16:11]
(   lgr_stk_ses)(6503602   )  SIPStackSession::HandleStackSetupEV - NEWCALL: SrcPN=0 [Time: 15:16:11]
(   lgr_stk_ses)(6503603   )  <SESSION #471> SendToCall - event: NEW_CALL_EV  m_Call#5 [Time: 15:16:11]
(      lgr_flow)(6503604   )  |       |       #5:NEW_CALL_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503605   )  |       |       #5:Call changing states from:IdleState to:NewCallState_IP2Tel [Time: 15:16:11]
(      lgr_flow)(6503606   )  ServicesMngr::GetEndPoint PhoneNum = 18773526710
 [Time: 15:16:11]
(   lgr_psbrdif)(6503607   )  GetTrunkGroupId- TrunkGroup:1 Trunk:-1 found DstNum:18773526710 DstPfx:* SrcNum:+1603xxxxxxx SrcPfx:* SrcIp:a050060 SrcIpPfx:* [Time: 15:16:11]
(   lgr_psbrdif)(6503608   )  Current trunks status: 1 [Time: 15:16:11]
(      lgr_call)(6503609   )  Call::SetCoderListForCall #5 Found 3 Common Coders For Call [Time: 15:16:11]
(      lgr_call)(6503610   )  <Call #5> Coder g711Ulaw64k20 : 20 [Time: 15:16:11]
(      lgr_call)(6503611   )  <Call #5> Coder g72920 : 20 [Time: 15:16:11]
(      lgr_call)(6503612   )  <Call #5> Coder t38fax : 255 [Time: 15:16:11]
( lgr_profiling)(6503613   )  <Call 5> Profiled<Tel=1,Ip=1>: JBMinDel=10 JBOptF=10 EEarlyM=1 FaxTM=0 IPDS=46 IsFaxU=1 PI2IP=8 SigIPDF=40 CNGMode=0 DTMFUsed=0 NSEMode=0 PlayRBTone2IP=0 RBUdpPort=0 RTPRD=0 SCE=0 VxxTT=2 Dst2Rdrt=0 DTMFVol=20 ECE=1 ECurDis=1 EDigDel=1 ERevP=0 FHPer=700 InG=32 MWIA=0 MWID=0 VVol=32 ReorderTime=255 DIDWink=1 2StageDial=1 DiscOnBusyT=1 DiscOnBrok=0 DPInd=-1 AGC=0 NLP=0 [Time: 15:16:11]
(      lgr_call)(6503614   )  |       |       #5GetNextUI:GlobalUI=963582912, mACAddrLsb=3450075 [Time: 15:16:11]
(      lgr_call)(6503615   )  |       |       #5GetNextUI:GlobalUI=963582913 [Time: 15:16:11]
(      lgr_flow)(6503616   )  |       #52:NEW_CALL_EV   : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(lgr_media_service)(6503617   )  MscmlSignalFeature Allocated ResourceID: 136 [Time: 15:16:11]
(      lgr_flow)(6503618   )  EndPoint channel# 52 ::Active DSP ChannelsCounter (D|A)= 1|12  [Time: 15:16:11]
(      lgr_flow)(6503619   )  EndPoint::MediaResourceList::AllocateMediaIpPortsByMediaRealmID Perform NEW allocation of Media ports for RealmIndex(0) port(8890) current allocations are:(1) [Time: 15:16:11]
(     sip_stack)(6503620   )  SIPSDPSession#471 - Changing state from SIP_MEDIA_IDLE to SIP_MEDIA_OFFERED [Time: 15:16:11]
(     sip_stack)(6503621   )  <BaseSIP SDPSESSION #471> UpdateChosenMediaByCN - CN as Remote 1 [Time: 15:16:11]
(     sip_stack)(6503622   )  <BaseSIP SDPSESSION #471> UpdateChosenMediaByCN - Force silence suppression on chosen coder, because remote & local support CN [Time: 15:16:11]
(      lgr_flow)(6503623   )  |       |(SIPTU#480)TRYING_REQ State:Invited(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(     sip_stack)(6503624   )  New SIPMessage created - #49 [Time: 15:16:11]
(      lgr_flow)(6503625   )  ---- Outgoing SIP Message to 10.5.0.96:56057 from SIPInterface #0 ---- [Time: 15:16:11]
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK3f1494f2
From: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
To: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
Call-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
CSeq: 16403 INVITE
Supported: em,timer,replaces,path,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.20A.056.006
Content-Length: 0
 [Time: 15:16:11]
(     sip_stack)(6503627   )  Resource SIPMessage deleted - #49 [Time: 15:16:11]
(   lgr_stk_ses)(6503628   )  SIPStackSession::HandleStackSetupEV - SETUP: SrcPN=0 [Time: 15:16:11]
(   lgr_stk_ses)(6503629   )  <SESSION #471> SendToCall - event: SETUP_EV  m_Call#5 [Time: 15:16:11]
(      lgr_flow)(6503630   )  |       |       #5:SETUP (TO:18773526710, FROM:+1603xxxxxxx):(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503631   )  |       |       #5:Call changing states from:NewCallState_IP2Tel to:InitiatedState_IP2Tel [Time: 15:16:11]
(      lgr_flow)(6503632   )  |       #52:SETUP_EV   : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(lgr_media_service)(6503633   )  #52:SignalSubscribtionState changing states from:SUBSCRIBTION_STATE_IDLE to:SUBSCRIBTION_STATE_READY [Time: 15:16:11]
(   lgr_psbrdif)(6503634   )  pstn send --> PlaceCall: Trunk:0 BChannel:23 ConnID:0 SrcPN=+1603xxxxxxx SrcSN= DstPN=18773526710 DstSN= SrcNT=0 SrcNP=0 SrcPres=0 SrcScrn=0 DstNT=0 DstNP=0 ServiceCap=M RdrctNum= RdNT=0 RdNP=0 RdPres=0 RdScrn=0 RdRsn=-1 Excl=0 Display=Pam McLeod IE= UUIE=0, RawData:0 CLIRReason:-1 OrigPN= OLI=-1 OffhookInd=0 [Time: 15:16:11]
(     sip_stack)(6503635   )  Resource SIPMessage deleted - #166 [Time: 15:16:11]
(   lgr_psbrdex)(6503636   )  pstn recv <-- CALL_PROCEEDING Trunk:0 Conn:0 BChannel:23  callhndl:0 Loc:-1 Des:-1 [Time: 15:16:11]
(      lgr_flow)(6503637   )  #52:LOCAL_CALL_PROCEEDING_EV(Trunk:0 Conn:0 Bchannel:23 TpEv=73) [Time: 15:16:11]
(      lgr_flow)(6503638   )  |       #52:LOCAL_CALL_PROCEEDING_EV [Time: 15:16:11]
(      lgr_flow)(6503639   )  |       #52:PROGRESS_INDICATOR_EV (send)  : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503640   )  |       |       #5:PROGRESS_INDICATOR_EV(PI=-1)(PC=-1):(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503641   )  |       #52:PROCEEDING_EV (send)  : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503642   )  |       |       #5:PROCEEDING_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503643   )  |       |       |       #471:PROCEEDING_EV(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(     sip_stack)(6503644   )  New SIPMessage created - #56 [Time: 15:16:11]
(     sip_stack)(6503645   )  SIPSDPSession#471 - Changing state from SIP_MEDIA_OFFERED to SIP_MEDIA_COMPLETED [Time: 15:16:11]
(   lgr_stk_ses)(6503646   )  DtmfCapNegotiationAlgorithm :: TxDtmfMethod = DTMF_RFC2833_SUPPORTED [Time: 15:16:11]
(   lgr_stk_ses)(6503647   )  DtmfCapNegotiationAlgorithm :: TxRtpRfc2833Payload = 101 [Time: 15:16:11]
(   lgr_stk_ses)(6503648   )  <SESSION #471> SendToCall - event: DTMF_CONTROL_EV  m_Call#5 [Time: 15:16:11]
(      lgr_flow)(6503649   )  |       |       #5:DTMF_CONTROL_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(   lgr_stk_ses)(6503650   )  <SESSION #471> SendToCall - event: OPEN_LOGICAL_CHANNEL_ACK_EV  m_Call#5 [Time: 15:16:11]
(      lgr_flow)(6503651   )  |       |       #5:OPEN_LOGICAL_CHANNEL_ACK_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503652   )  |       #52:OPEN_LOGICAL_CHANNEL_ACK_EV   : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503653   )  |       #52:OPEN_VOICE (IP:10.5.0.96, RTP:55720, RTCP:0, VoiceCoder:g711Ulaw64k20, VbdCoder: InvalidCoder255, Dtmf:gwRFC2833RalayDTMF,Rx payload:101,Tx payload:101 ,RTPmode:1, FaxTransportType: 1, AVoIPMediaType: gwMediaTypeAudioOnly, T38Version:N/A, FaxMaxBR:0) [Time: 15:16:11]
(   lgr_psbrdif)(6503654   )  activate channel local rtp port:8890, port=55720, BChannel:23, local ip:10.5.0.98, ip=10.5.0.96 (Voice:1,Vbd:0,T38:0,Video:0) [Time: 15:16:11]
(   lgr_psbrdif)(6503655   )  #52:ActivateChannel: Socks=0 CID=52 Trunk:0 BChannel:23 RemoteIP=10.5.0.96 RemotePort=55720 RemoteT38IP= RemoteT38Port=0 RemoteRTCPIP= RemoteRTCPPort=0 FaxModemDet=NO_FAX_MODEM_DETECTED [Time: 15:16:11]
(   lgr_psbrdif)(6503656   )  Open channel: IsVoiceOn: 1, IsT38On: 0, IsVbdOn: 0, IsVideoOn: 0 [Time: 15:16:11]
(   lgr_psbrdif)(6503657   )  #52:OpenChannel:on Trunk 0 BChannel:23 CID=52 with VoiceCoder: g711Ulaw64k20 VbdCoder: InvalidCoder255 DetectorSide: 0 FaxModemDet NO_FAX_MODEM_DETECTED [Time: 15:16:11]
(   lgr_psbrdif)(6503658   )  #52:OpenChannel VoiceVolume= 0, DTMFVolume = -11, InputGain = 0, RTPRedundancyDepth = 0 FlashHookPeriod = 700 AgcCmd = 0x13180000
 [Time: 15:16:11]
(   lgr_psbrdif)(6503659   )  RFC2833RTPPayloadType: Rx=101 Tx=101 [Time: 15:16:11]
(   lgr_psbrdif)(6503660   )  OpenChannel, CoderType = 1, Interval = 3, M = 1
 [Time: 15:16:11]
(   lgr_psbrdif)(6503661   )  #52:FAXTransportType = 1 [Time: 15:16:11]
(   lgr_psbrdif)(6503662   )  ConfigureVbdAndT38:FAXTransportType 1 T38Version:0 [Time: 15:16:11]
(   lgr_psbrdif)(6503663   )  #52:ConfigFaxModemChannelParams NSEMode=0, CNGDetMode=0, FAXTranType=1, VxxTranType=2, VoiceVol= 0, DTMFVol=-11, InGain=0, RTPRedDepth=0, ECE=1, SCE=1, ECNlpMode=0, DJBufMinDelay=10, DJBufOptFac=10, Result=1) [Time: 15:16:11]
(   lgr_psbrdif)(6503664   )  Detectors: Amd:On=0,Diretion=0, Ans:On=0,Direction=0 En:On=0,Direction=0 Board IBScmd:0xa1 [Time: 15:16:11]
(   lgr_psbrdif)(6503665   )  #52:Channel will be open WITH DSP [Time: 15:16:11]
(   lgr_psbrdif)(6503666   )  Setting ActivateRTP_RTCPCmd.Cmd.IpTosFieldInUdpPacket to 184 [Time: 15:16:11]
(   lgr_psbrdif)(6503667   )  #52:ActivateChannel:RtpPayload: 0 [Time: 15:16:11]
(      lgr_flow)(6503668   )  |       |(SIPTU#480)ALERT_REQ State:Invited(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503669   )  ---- Outgoing SIP Message to 10.5.0.96:56057 from SIPInterface #0 ---- [Time: 15:16:11]
SIP/2.0 183 Session Progress
Via: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK3f1494f2
From: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
To: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
Call-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
CSeq: 16403 INVITE
Contact: <sip:1022@10.5.0.98:5060;transport=tcp>
Supported: em,timer,replaces,path,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Require: 100rel
RSeq: 1
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.20A.056.006
Content-Type: application/sdp
Content-Length: 253
v=0
o=AudiocodesGW 1317979725 1317960414 IN IP4 10.5.0.98
s=Phone-Call
c=IN IP4 10.5.0.98
t=0 0
m=audio 8890 RTP/AVP 0 13 101
c=IN IP4 10.5.0.98
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15,16
a=ptime:20
a=sendrecv
 [Time: 15:16:11]
(     sip_stack)(6503671   )  Resource SIPMessage deleted - #56 [Time: 15:16:11]
(     sip_stack)(6503672   )  New SIPMessage created - #135 [Time: 15:16:11]
(      lgr_flow)(6503673   )  ---- Incoming SIP Message from 10.5.0.96:56057 to SIPInterface #0 ---- [Time: 15:16:11]
PRACK sip:1022@10.5.0.98:5060;transport=tcp SIP/2.0
FROM: <sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
TO: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
CSEQ: 16404 PRACK
CALL-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK27d234b1
CONTACT: <sip:acsLync1.alton.school.com:5060;transport=Tcp;maddr=10.5.0.96>
CONTENT-LENGTH: 0
USER-AGENT: RTCC/4.0.0.0 MediationServer
RAck: 1 16403 INVITE
 [Time: 15:16:11]
(      lgr_flow)(6503675   )  |       |(SIPTU#480)PRACK State:Invited(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(     sip_stack)(6503676   )  New SIPMessage created - #150 [Time: 15:16:11]
(     sip_stack)(6503677   )  Resource SIPMessage deleted - #150 [Time: 15:16:11]
(      lgr_flow)(6503678   )  |       |       |       #471:SIP_PRACK_EV(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(     sip_stack)(6503679   )  New SIPMessage created - #151 [Time: 15:16:11]
(     sip_stack)(6503680   )  New SIPMessage created - #3 [Time: 15:16:11]
[Src=10.5.0.96/55720 Dst=8890 PType=6] ErrMgs=9 Invalid RTP version (= 0) 
 [Code:3700e] [CID:52] [Time: 15:16:11]
[Src=10.5.0.96/55721 Dst=8891 PType=6] ErrMgs=7 Invalid RTCP packet type:  RtcpVer = 0  RtcpPt = 1
 [Code:3700e] [CID:52] [Time: 15:16:11]
(      lgr_flow)(6503681   )  |       |(SIPTU#480)PRACK_RESPONSE State:Invited(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:11]
(      lgr_flow)(6503682   )  ---- Outgoing SIP Message to 10.5.0.96:56057 from SIPInterface #0 ---- [Time: 15:16:11]
SIP/2.0 200 OK
Via: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK27d234b1
From: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
To: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
Call-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
CSeq: 16404 PRACK
Contact: <sip:1022@10.5.0.98:5060;transport=tcp>
Supported: em,timer,replaces,path,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.20A.056.006
Content-Length: 0
 [Time: 15:16:11]
(     sip_stack)(6503684   )  Resource SIPMessage deleted - #3 [Time: 15:16:11]
(     sip_stack)(6503685   )  Resource SIPMessage deleted - #151 [Time: 15:16:11]
(     sip_stack)(6503686   )  Resource SIPMessage deleted - #135 [Time: 15:16:11]
IR:2 RP:3  [Code:5004] [CID:52] [Time: 15:16:12]
(   lgr_psbrdex)(6503687   )  pstn recv <-- CALL_DISCONNECTED Trunk:0 Conn:0 RetCause:104 NetCause:111 [Time: 15:16:12]
(   lgr_psbrdif)(6503688   )  Abnormal Disconnect cause:111#GWAPP_PROTOCOL_ERROR_UNSPECIFIED Trunk:0 Conn:0 [Time: 15:16:12]
(      lgr_flow)(6503689   )  #52:LOCAL_CALL_DISCONNECTED_EV(Trunk:0 Conn:0 Bchannel:23 TpEv=67) [Time: 15:16:12]
(      lgr_flow)(6503690   )  |       #52:LOCAL_CALL_DISCONNECTED_EV [Time: 15:16:12]
(      lgr_flow)(6503691   )  |       #52:Close voice Channel [Time: 15:16:12]
(   lgr_psbrdif)(6503692   )  #52:StopRTP_RTCP on channel 52 [Time: 15:16:12]
(      lgr_flow)(6503693   )  |       #52:RELEASE_EV (send) GWAPP_PROTOCOL_ERROR_UNSPECIFIED : (78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(      lgr_flow)(6503694   )  |       |       #5:RELEASE_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(      lgr_flow)(6503695   )  |       |       #5:Call changing states from:InitiatedState_IP2Tel to:DisconnectingState [Time: 15:16:12]
|CALL_END    |52   |0              |0    |23   |0    |1    |ISDN      |RMT  |10.5.0.96           |10.5.0.98           |0    |0    |+1603xxxxxxx        |+1603xxxxxxx        |0    |0    |18773526710         |18773526710         |0    |g711Ulaw64k    |20   |10.5.0.96           |55720|LCL  |GWAPP_PROTOCOL_ERROR_UNSPECIFIED        |0    |0         |7         |0         |0             |78a03459-84ff-4f9d-b8ca-f0bab9e35e5d              |15:16:11.000  UTC     Mar 11 2014  |                                   |15:16:12.000  UTC     Mar 11 2014  |0        |0        |701166755 |191201174     |-1             |0    |0    |                    |0                   |                    |                    |                    |                    |1    |10.5.0.98           |8890 |         |     
 [Time: 15:16:12]
(      lgr_flow)(6503697   )  |       |       #5:RELEASE_ACK_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(      lgr_flow)(6503698   )  EndPoint::MediaResourceList::FreeMediaIpPorts Perform dellocation of Media ports for RealmIndex(0) port(8890) current allocations are:(0) [Time: 15:16:12]
(      lgr_flow)(6503699   )  |       |       |       #471:RELEASE_EV(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(     sip_stack)(6503700   )  New SIPMessage created - #167 [Time: 15:16:12]
(      lgr_flow)(6503701   )  |       |(SIPTU#480)DISCONNECT_REQ State:Invited(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(      lgr_flow)(6503702   )  ---- Outgoing SIP Message to 10.5.0.96:56057 from SIPInterface #0 ---- [Time: 15:16:12]
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK3f1494f2
From: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;epid=452011D619;tag=8c118c7c31
To: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
Call-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
CSeq: 16403 INVITE
Supported: em,timer,replaces,path,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
Server: Audiocodes-Sip-Gateway-Mediant 1000 - MSBG/v.6.20A.056.006
Reason: Q.850 ;cause=111
Content-Length: 0
 [Time: 15:16:12]
(     sip_stack)(6503704   )  SIPCall(#480) changes state from Invited to Disconnected [Time: 15:16:12]
(   lgr_stk_ses)(6503705   )  <SESSION #471> SendToCall - event: RELEASE_ACK_EV  m_Call#5 [Time: 15:16:12]
(      lgr_flow)(6503706   )  |       |       #5:RELEASE_ACK_EV:(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(      lgr_call)(6503707   )  (#5) Call DeAllocated. [Time: 15:16:12]
(      lgr_call)(6503708   )  delete GW call current active is: 1 [Time: 15:16:12]
(     sip_stack)(6503709   )  AcSIPStackAPI::FreeCallAPI - #20 [Time: 15:16:12]
(     sip_stack)(6503710   )  Setting ApplicationCall of AcSIPCall 789439512 to NULL [Time: 15:16:12]
(  lgr_stk_mngr)(6503711   )  Resource StackSession <#471> Deleted [Time: 15:16:12]
(     sip_stack)(6503712   )  Resource SIPMessage deleted - #167 [Time: 15:16:12]
(   lgr_psbrdif)(6503713   )  pstn send --> psPSTNReleaseCall() Trunk:0 Conn:0 BChannel:23 Reason:111 rc:0 0x0 [Time: 15:16:12]
(     sip_stack)(6503714   )  New SIPMessage created - #84 [Time: 15:16:12]
(      lgr_flow)(6503715   )  ---- Incoming SIP Message from 10.5.0.96:56057 to SIPInterface #0 ---- [Time: 15:16:12]
ACK sip:18773526710@10.5.0.98;user=phone SIP/2.0
FROM: "Pam McLeod"<sip:+1603xxxxxxx;ext=9xxx@acslync1.alton.school.com;user=phone>;tag=8c118c7c31;epid=452011D619
TO: <sip:18773526710@10.5.0.98;user=phone>;tag=1c1311236781
CSEQ: 16403 ACK
CALL-ID: 78a03459-84ff-4f9d-b8ca-f0bab9e35e5d
MAX-FORWARDS: 70
VIA: SIP/2.0/TCP 10.5.0.96:56057;branch=z9hG4bK3f1494f2
CONTENT-LENGTH: 0
 [Time: 15:16:12]
(      lgr_flow)(6503717   )  |       |(SIPTU#480)ACK State:Disconnected(78a03459-84ff-4f9d-b8ca-f0bab9e35e5d) [Time: 15:16:12]
(     sip_stack)(6503718   )  Resource SIPMessage deleted - #84 [Time: 15:16:12]
(   lgr_psbrdex)(6503719   )  pstn recv <-- CALL_RELEASED Trunk:0 Conn:0 RetCause:104 NetCause:111 [Time: 15:16:12]
(   lgr_psbrdif)(6503720   )  Abnormal Disconnect cause:111#GWAPP_PROTOCOL_ERROR_UNSPECIFIED Trunk:0 Conn:0 [Time: 15:16:12]
(      lgr_flow)(6503721   )  #52:LOCAL_CALL_RELEASED_EV(Trunk:0 Conn:0 Bchannel:23 TpEv=68) [Time: 15:16:12]
(      lgr_flow)(6503722   )  |       #52:LOCAL_CALL_RELEASED_EV [Time: 15:16:12]
(   lgr_psbrdif)(6503723   )  #52:cpDigitMapHndlr_Stop - Stoped (0) [Time: 15:16:12]
(   lgr_psbrdif)(6503724   )  #52:CloseChannel: ChannelNum=52 [Time: 15:16:12]
(lgr_media_service)(6503725   )  MscmlSignalFeature Returned to Pool ResourceID: 136 [Time: 15:16:12]
(      lgr_flow)(6503726   )  EndPoint channel# 52 ::Active DSP ChannelsCounter (D|A)= 0|12  [Time: 15:16:12]
(     sip_stack)(6503727   )  New SIPMessage created - #22 [Time: 15:16:16]
(     sip_stack)(6503728   )  Resource SIPMessage deleted - #22 [Time: 15:16:16]
(      lgr_flow)(6503729   )  |       | TransactionUserMngr::ReturnSIPCall - #480 [Time: 15:16:16]
(     sip_stack)(6503730   )  SIPCall(#480) changes state from Disconnected to Idle [Time: 15:16:16]
(      lgr_flow)(6503731   )  TcpTransportObject#373- CTcpClientSocket::HandleSocketEvent socket close/reset [Time: 15:16:27]
(     sip_stack)(6503732   )  TcpTransportObject#373::CloseConnection - Closing connection [Time: 15:16:27]
(     sip_stack)(6503733   )  Socket buffer released - #120 [Time: 15:16:27]
(     sip_stack)(6503734   )  SIPTCPMngr::ReturnTCPTransportObj - #373 [Time: 15:16:27]

You did not include full trace for the call. I need to see the start of the call and end. If I saw the end of the call, I would see how the number arrived and what happened to the number.

In any case, I see the following:

The number that you are trying to dial is 18773526710. I cannot tell you why carrier is rejecting your call, but it is possible that you are using Lync certified carrier and they require + in front of the number. I think that one of your manipulation rules on your gateway removes + from the number.

Stop removing + and test it. In any case, if it still does not work, call them and ask why the call is being rejected. They should be able to check logs and tell you what is wrong with the number.

Thanks Igor. I thought about the number formatting, but I don't think that's the issue. There are a few 877 numbers that work, and I tried every possible combination to rule out formatting issues.

Our carrier is working on it at this point, especially since I've discovered that some 877 numbers work and some do not. This forum has been helpful, I'll keep everyone posted!

Here's a quick update: turns out it is a mix of 800, 877, 855, and 866 numbers, most from the toll-free carrier Global Crossing. Our provider is doing some tracing for us. Calls from a regular FAX line (centrex) work, but not the calls that go out through the PRI, so it is specific to ISDN traffic (from what I heard the engineers saying) - it was a protocol error code 111 on their Tandem.

TON/NPI were set to No on my Audiocodes, I turned them on after school, and they did not make a difference.

Our provider will do more detailed tracing for us tomorrow - they've been great.

Hi Pam,

            from the trace the Q.850 cause code of 111 was produced from the carrier side, unfortunately 111 correlates to an upsecified error. Just for reference, your gateway is running very old firmware (v.6.20A.056.006) version 6.8 was released a few weeks ago, you will be entitled to this if you a valid maintenance agreement with AudioCodes. Thanks.

Regards.

This issue is still not resolved. We have very limited testing time available to bring the phones down. The Audiocodes firmware was updated with no change. The telco has tested with a PRI test handset from within our building (at their HDSL device, which is their last equipment before our Audiocodes), and can dial the toll-free numbers without issue.

I feel as if there is some kind of parameter or setting on the Audiocodes that is missing, but various Lync engineers are telling me that it is just about digits (and the digits are fine). The Telco can't seem to give me a list of parameters/settings that are required of us.

• Edited by pmcleod 21 hours 34 minutes ago edit

This issue is still not resolved. We have very limited testing time available to bring the phones down. The Audiocodes firmware was updated with no change. The telco has tested with a PRI test handset from within our building (at their HDSL device, which is their last equipment before our Audiocodes), and can dial the toll-free numbers without issue.

I feel as if there is some kind of parameter or setting on the Audiocodes that is missing, but various Lync engineers are telling me that it is just about digits (and the digits are fine). The Telco can't seem to give me a list of parameters/settings that are required of us.

• Edited by pmcleod Wednesday, April 09, 2014 1:30 PM edit