01-07-2011 08:13 AM - edited 03-16-2019 02:45 AM
Hi,
I have a problem with my corporate mobile phones which are configured as remote destinations.
- Phone A calls Phone B (both internal)
- A PSTN phone calls phone A and hears a busy tone --> everything good so far
- If instead of a random PSTN phone a corporate mobile phone (which is configured as a remote destination) tries to call phone A, the mobile phone user hears nothing (silence) instead of the busy tone.
The setup is as follows:
- CUCM v8.0.3.20000-2
- IP Phone 8961
- every user has a 8961 phone, a CSF device (for CUPC softphone), a RDP with RD,
so in other words a shared line which is configured on 3 devices (all with busy trigger = 1)
PSTN --> H.323 Gateway --> CUCM
A successful call (random PSTN phone, busy tone ok) does not seam to appear in IP Voice Media Streaming App traces.
An unsuccessful call (remote destination calling, no busy tone) appears in IP Voice Media Streaming App traces as follows:
e.g.: 15:04:44.993 | IpPlayWav::Play (21,40503340,0) Play (/usr/local/cm/tftp/switzerland/AnnBusyTone.ulaw.wav)
IP Voice Media Streaming App traces snippet
15:04:44.980 | CStimulusMsg::HandleRecMessage len(120) Message ID = [138]
15:04:44.980 |-->[ANN][172.22.15.71] DeviceMgr::recvStationStartMediaTransmissionMsg
15:04:44.980 | [ANN][172.22.15.71] DeviceMgr::recvStationStartMediaTransmissionMsg Application ID = 21, ConferenceID = 40503340, PassThruPartyID = 33554872, RFC2833PayloadType = 0
15:04:44.980 | [ANN][172.22.15.71] DeviceMgr::recvStationStartMediaTransmissionMsg Sending StationStartMediaTransmissionAck, resultCode = 0
15:04:44.980 |-->[ANN][172.22.15.71]CTTCPSocket::SendOut
15:04:44.980 |<--[ANN][172.22.15.71]CTTCPSocket::SendOut
15:04:44.980 |<--[ANN][172.22.15.71] DeviceMgr::recvStationStartMediaTransmissionMsg
15:04:44.980 |<--CStimulusMsg::HandleRecMessage len(120)
15:04:44.980 |<--[ANN][172.22.15.71] DeviceMgr::OnRecInStimMessage
15:04:44.980 | [ANN][172.22.15.71]CTTCPSocket::SocketReadThread REC in nBytesRead = [468] pData=[0xb543ef20] Sending To Users Callback
15:04:44.980 |-->[ANN][172.22.15.71] DeviceMgr::OnRecInStimMessage
15:04:44.980 | [ANN][172.22.15.71] DeviceMgr::OnRecInStimMessage pData = 0xb543ef20
15:04:44.980 | [ANN][172.22.15.71] DeviceMgr::OnRecInStimMessage Len = 468
15:04:44.980 |-->CStimulusMsg::HandleRecMessage len(468)
15:04:44.980 | CStimulusMsg::HandleRecMessage len(468) Message ID = [290]
15:04:44.980 |-->[ANN][172.22.15.71] DeviceMgr::recvStationStartAnnouncementMessage
15:04:44.980 | [ANN][172.22.15.71] DeviceMgr::recvStationStartAnnouncementMessage AppID(21), Conf(40503340), Country/Locale/AnnID(59/1/35) AckReq(0) Mode(Repeat)
15:04:44.980 |-->CPlayWavFilesMgr::Play aid(21) cid(40503340)
15:04:44.980 | CPlayWavFilesMgr::Play aid(21) cid(40503340) PayloadType: 4
15:04:44.980 |-->CANNAudio::GetAnnouncement()
15:04:44.980 |-->CANNAudio::GetCodecString(4)
15:04:44.980 |<--CANNAudio::GetCodecString(4)
15:04:44.980 | CANNAudio::GetAnnouncement() LocaleID(1) CountryID(59) AnnID(35) payload(.ulaw)
15:04:44.980 | CANNAudio::GetAnnouncement() Ann(Busytone) AnnBusyTone.wav(NW) AnnBusyTone.wav(NW)
15:04:44.980 |-->CANNAudio::isFileExist(AnnBusyTone.wav)
15:04:44.980 | CANNAudio::isFileExist(AnnBusyTone.wav) isUserLocale(F) UserLocale(1) nwLocale(59) isCustom(F)
15:04:44.980 |-->CANNAudio::GetCodecString(4)
15:04:44.980 |<--CANNAudio::GetCodecString(4)
15:04:44.981 | [ANN][172.22.15.71]CTSocket::SocketWriteThread Handling write events
15:04:44.981 |-->[ANN][172.22.15.71]CTTCPSocket::HandleWrite
15:04:44.981 |<--[ANN][172.22.15.71]CTTCPSocket::HandleWrite
15:04:44.981 | CSignalHandler::ProcessThreadProc() log 451
15:04:44.981 | [ANN][172.22.15.71]CTSocket::SocketWriteThread Wait for m_hWriteSignalSemaphore
15:04:44.981 | [ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents Removed Event=451 from signaled list, index=2, now size=0
15:04:44.981 | [ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents Returned from wait on MEvent=551, ret=0, retCode=2
15:04:44.981 |<--[ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents
15:04:44.981 | [ANN][172.22.15.71] DeviceMgr::ProcessThreadProc Returned from wait, ret=2
15:04:44.981 |-->[ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents
15:04:44.981 | [ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents ANN: New TX AId=21 CId=40503340 PId=33554872 Size=20 Type=4 PS=B8 SS=1 IP=172.22.15.79:18668(25154) Multicast=N UserMode=N 2833PL=0 UBsz=0 USig=0/0
15:04:44.981 |<--[ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents
15:04:44.981 |-->[ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D5 0x37872B1F
15:04:44.981 | [ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D5 0x37872B1F State = ST_REGISTERED, m_Timeout = 931605279
15:04:44.981 |<--[ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D5 0x37872B1F
15:04:44.981 |-->[ANN][172.22.15.71]CMsgQueue::PeekMessage()
15:04:44.981 | [ANN][172.22.15.71]CMsgQueue::PeekMessage() Message queue is empty
15:04:44.981 |<--[ANN][172.22.15.71]CMsgQueue::PeekMessage()
15:04:44.981 | [ANN][172.22.15.71] DeviceMgr::ProcessThreadProc Wait for 449,450,451 - m_hExitEvent=449,m_SocketNotifyEvent=450,m_hDrvNotifyEvent=451
15:04:44.981 |-->[ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents
15:04:44.981 |-->[ANN][172.22.15.71] CEventHandler::AddWaitCountForMultipleEvents()
15:04:44.981 | [ANN][172.22.15.71] CEventHandler::AddWaitCountForMultipleEvents() For thread=b47ffba0, found MEvent=551 waitCount=1
15:04:44.981 |<--[ANN][172.22.15.71] CEventHandler::AddWaitCountForMultipleEvents()
15:04:44.981 | [ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents Waiting on MEvent=551
15:04:44.993 |<--CANNAudio::isFileExist(AnnBusyTone.wav)
15:04:44.993 | CANNAudio::GetAnnouncement() Ann(Busytone) File(/usr/local/cm/tftp/switzerland/AnnBusyTone.ulaw.wav)
15:04:44.993 |<--CANNAudio::GetAnnouncement()
15:04:44.993 |-->CMsgQueue::PostThreadMessage()
15:04:44.993 | CMsgQueue::PostThreadMessage() Message enqueued, MsgType=1026, wP=0, lP=-1253847672, queueSize=1
15:04:44.993 |<--CMsgQueue::PostThreadMessage()
15:04:44.993 |<--CPlayWavFilesMgr::Play aid(21) cid(40503340)
15:04:44.993 |<--[ANN][172.22.15.71] DeviceMgr::recvStationStartAnnouncementMessage
15:04:44.993 |<--CStimulusMsg::HandleRecMessage len(468)
15:04:44.993 |<--[ANN][172.22.15.71] DeviceMgr::OnRecInStimMessage
15:04:44.993 | CMsgQueue::GetMessage() Message dequeued, MsgType=1026, wP=0, lP=-1253847672, queueSize=0
15:04:44.993 |<--CMsgQueue::GetMessage()
15:04:44.993 |-->CPlayWavFilesMgr::ProcessStartPlay
15:04:44.993 |-->CPlayWavFilesMgr::Find
15:04:44.993 |<--CPlayWavFilesMgr::Find
15:04:44.993 |-->IpPlayWav::Play (21,40503340,0)
15:04:44.993 | IpPlayWav::Play (21,40503340,0) Play (/usr/local/cm/tftp/switzerland/AnnBusyTone.ulaw.wav) I(0) (/usr/local/cm/tftp/switzerland/AnnBusyTone.ulaw.wav)
15:04:44.993 | IpPlayWav::Play (21,40503340,0) Whisper (0,0,0,0) 0x0000
15:04:44.993 |-->CIpPlayWav::StartPlaying.ST_PLAYING_FIRST (21,40503340,0)
15:04:44.993 |-->IpPlayWav::OpenWav (21,40503340,0)
15:04:44.993 |<--IpPlayWav::OpenWav (21,40503340,0)
15:04:44.993 |-->IpPlayWav::StartMediaMsg (21,40503340,0)
15:04:44.993 | IpPlayWav::StartMediaMsg (21,40503340,0) Start USR RX: RxListCnt(0)
15:04:44.993 |<--IpPlayWav::StartMediaMsg (21,40503340,0)
15:04:44.993 |<--CIpPlayWav::StartPlaying.ST_PLAYING_FIRST (21,40503340,0)
15:04:44.993 |-->CIpPlayWav::SendMoreData.ST_PLAYING_FIRST (21,40503340,0)
15:04:44.993 | CSignalHandler::ProcessThreadProc() log 451
15:04:44.993 | [ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents Removed Event=451 from signaled list, index=2, now size=0
15:04:44.993 | [ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents Returned from wait on MEvent=551, ret=0, retCode=2
15:04:44.993 |<--[ANN][172.22.15.71] CEventHandler::WaitForMultipleEvents
15:04:44.993 | [ANN][172.22.15.71] DeviceMgr::ProcessThreadProc Returned from wait, ret=2
15:04:44.993 |-->[ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents
15:04:45.001 |<--CIpPlayWav::SendMoreData.ST_PLAYING_FIRST (21,40503340,0)
15:04:45.001 |<--IpPlayWav::Play (21,40503340,0)
15:04:45.001 | CPlayWavFilesMgr::ProcessStartPlay Active Playing: 1
15:04:45.001 |<--CPlayWavFilesMgr::ProcessStartPlay
15:04:45.001 |-->CMsgQueue::GetMessage()
15:04:45.001 | [ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents ANN: New RX AId=21 CId=40503340 PId=0 Size=20 Type=4 PS=B8 SS=0 IP=172.22.15.71:0(0) Multicast=N UserMode=Y 2833PL=0 UBsz=4000 USig=40/531
15:04:45.001 |<--[ANN][172.22.15.71] DeviceMgr::ProcessDriverEvents
15:04:45.001 |-->[ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D7 0x37872B1F
15:04:45.001 | [ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D7 0x37872B1F State = ST_REGISTERED, m_Timeout = 931605279
15:04:45.001 |<--[ANN][172.22.15.71] DeviceMgr::TimeCheck 0x378720D7 0x37872B1F
15:04:45.001 |-->[ANN][172.22.15.71]CMsgQueue::PeekMessage()
15:04:45.001 | [ANN][172.22.15.71]CMsgQueue::PeekMessage() Message queue is empty
Any ideas? I couldn't find an error in the traces... Why does a call with no busy tone appear in the traces and one with busy tone does not?
By the way: reboot of the CUCM server didn't help.
Thanks,
lukas
01-09-2011 11:44 PM
A colleague seemed to have the same problem (though only with iPhones, I have it with all mobile phones)
His solutions was to add the commands "voice call convert-discpi-to-prog" and "voice call discpi-off" on the gateway
That means that all callers (when busy) get to hear an announcement like "this extension is currently not available" instead of a busy tone. That's basically not wrong but people are not used to hear an announcement like this when they would expect a busy tone.
By the way: if you don't enter "voice call discpi-off", you will hear a busy tone not only when busy but also when handing off a call from mobile to deskphone.
So, that's seems to be a nice workaround (which I haven't tried yet) but not really a valid solution for an endcustomer.
Is maybe somebody from Cisco reading this? Is there a known bug or something which could be solved with an upgrade?
thanks.
01-10-2011 07:09 AM
Hi Lukas,
I haven't seen this issue before. I would be interested to see the logs for this - would you be able to set the CallManager and IPVMS traces to detailed, reproduce the issue, and upload those logs to this thread ? Please let me know
- calling party
- called party
- time stamp of call
- exact user experience
A packet capture off the CallManager server which would be used as the Annunciator (https://supportforums.cisco.com/docs/DOC-11599) would also help.
- Sriram
01-11-2011 07:02 AM
Hi Sriram,
seems that others have had the same issue in the past. I received not only the answer I already posted above but also another suggestion.
If you put the H.323 gateway in a device pool with a MRGL that does not have an annunciator, it works.
I gave this a try and it seems to work.
Some more detailed debugging info I also received:
normal external user receives a 'disconnect - user busy' immediately
011645: Sep 16 18:55:27.682: ISDN BR0/0/0 Q931: TX -> DISCONNECT pd = 8 callref = 0x81
Cause i = 0x8091 - User busy
remote destination external user first receives a 'progress - user busy' and then after 30 sec only a 'disconnect - user busy'
011630: Sep 16 18:53:54.862: ISDN BR0/1/0 Q931: TX -> PROGRESS pd = 8 callref = 0x81
Cause i = 0x8191 - User busy
Progress Ind i = 0x8188 - In-band info or appropriate now available
011632: Sep 16 18:54:24.878: ISDN BR0/1/0 Q931: TX -> DISCONNECT pd = 8 callref = 0x81
Cause i = 0x8091 - User busy
If you still require the traces I can provide them end of week (I'm sick right now and not in the office...)
Thanks everybody for your help! I really appreciate it.
Lukas
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide