We are having an issue with so far 7962's some are advertsing G711 and others are stuck on G722 when being transfered to a UCCX or voicemail. User being transfered receives a busy.
Software Version: 8.5.1.14900-5
Problem Details: When internal phone transfers an internal extension to a script or
voicemail phone gets busy at transfer. This is not happening for all phones only a select
few.
Example of failure (traces attached)
Extension 55963 calls extension 55953
55963 answers call and hits transfer
55963 types 61800
55963 hears ring and UCCX Script associated with 61800
55963 hits transfer to connect 55953
55953 receives busy
Example of success (traces attached)
Extension 55953 calls extension 55963
55953 answers call and hits transfer
55953 types 61800
55953 hears ring and UCCX Script associated with 61800
55953 hits transfer to connect 55963
55963 receives busy
Example of failed call:
Phone A (53291) calls phone B
14:17:03.986 |StationInit: (0218199) SoftKeyEvent softKeyEvent=1(Redial) lineInstance=0 callReference=0.|5,100,50,1.246379688^10.4.19.66^SEP00269943BB0B
CI=89949961
14:17:03.988 ||PretransformCallingPartyNumber=53291
|CallingPartyNumber=53291
|DialingPartition=PT_INTERNAL_ONCLUSTER
|DialingPattern=55952
14:17:03.990 |StationD: (0217789) DEBUG- saveRinger for: ci=89949962, line=1, mode=2, cm_precedence=5, callPhase=5.|5,100,50,1.246379688^10.4.19.66^SEP00269943BB0B
14:17:03.993 |StationD: (0218199) StartTone tone=36(AlertingTone), direction=0.|5,100,50,1.246379688^10.4.19.66^SEP00269943BB0B
Phone B (55952) Answers the call.
14:17:05.624 |StationInit: (0217789) SoftKeyEvent softKeyEvent=11(Answer) lineInstance=1 callReference=89949962.|5,100,50,1.246379864^10.4.19.38^SEP00269943C946
Joining the two CI for the call to connect.
14:17:05.625 |ConnectionManager - wait_AuConnectRequest(89949961,89949962)|5,100,50,1.246379864^10.4.19.38^SEP00269943C946
Both the phones connect after negotiating G722 codec.
14:17:05.627 |StationD: (0217789) OpenReceiveChannel conferenceID=89949962 passThruPartyID=85516748 millisecondPacketSize=20 compressionType=6(Media_Payload_G722_64k) RFC2833PayloadType=0 qualifierIn=? sourceIpAddr=IpAddr.type:0 ipAddr:0x0a041342000000000000000000000000(10.4.19.66). myIP: IpAddr.type:0 ipv4Addr:0x0a041326(10.4.19.38) |5,100,216,1405271.1^*^*
14:17:05.626 |StationD: (0218199) OpenReceiveChannel conferenceID=89949961 passThruPartyID=85516747 millisecondPacketSize=20 compressionType=6(Media_Payload_G722_64k) RFC2833PayloadType=0 qualifierIn=? sourceIpAddr=IpAddr.type:0 ipAddr:0x0a041326000000000000000000000000(10.4.19.38). myIP: IpAddr.type:0 ipv4Addr:0x0a041342(10.4.19.66) |5,100,216,1405270.1^*^*
Phone B presses the Transfer Softkey for the first time and dials the other number
14:17:09.166 |StationInit: (0217789) SoftKeyEvent softKeyEvent=4(Trnsfer) lineInstance=1 callReference=89949962.|5,100,50,1.246380203^10.4.19.38^SEP00269943C946
14:17:12.263 ||PretransformCallingPartyNumber=55952
|CallingPartyNumber=55952
|DialingPartition=PT_INTERNAL_ONCLUSTER
|DialingPattern=61800
|FullyQualifiedCalledPartyNumber=61800
CI=89949989
Then the calls is answered by the CTI port
14:17:12.276 ||PretransformCallingPartyNumber=55952
|CallingPartyNumber=55952
|DialingPartition=PT_UCCX
|DialingPattern=2416
Now, the phone B presses the Transfer button for the second time.
14:17:15.216 |StationInit: (0217789) SoftKeyEvent softKeyEvent=4(Trnsfer) lineInstance=1 callReference=89949989.|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.225 |ConnectionManager - wait_AuConnectRequest(89949961,89950008)|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
Trying to Allocate a Trancoder from the phone’s MRGL (BOS_HW_MRG:Cluster_Software_MRG) and Default MRGL
14:17:15.228 |MediaResourceCdpc(463200)::createLookupTbl Name=XC-BOY02VOIPRT1 Cepn=a3090f65-b772-c7e0-711b-4c089697a291 Weight=0 Group=0 Counter=0|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::createLookupTbl Name=XC-PBX01VOIPRT1 Cepn=e0d11025-6e55-4cf2-f23a-846028b30264 Weight=0 Group=0 Counter=1|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.227 |MRM::getXcodeDeviceGivenMrgl GETTING XCODE FROM DEFAULT LIST|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::createLookupTbl Name=XC-CRBA6VOIPRT1 Cepn=0a8b3e97-bd7e-cc55-7e5f-498f6368cb19 Weight=0 Group=2 Counter=0|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::createLookupTbl Name=XC-PBX01VOIPRT2
Negotiating capabilities to allocate the Transcoder and it fails to match capabilities causing the call to fail.
14:17:15.228 |MediaResourceCdpc(463200)::waiting_MrmAllocateMtpResourceReq - CI=89950016 Count=1 TryPassThru=0|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::findDeviceGivenList - Name=XC-BOY02VOIPRT1 type=2 weight=0|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc::getNextMTPDevice MtpDevice=XC-BOY02VOIPRT1 Cepn=a3090f65-b772-c7e0-711b-4c089697a291 devCap=0 resoureCount=1|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::sendMtpAllocateRequestToDevice MtpResource=XC-BOY02VOIPRT1 Cepn=a3090f65-b772-c7e0-711b-4c089697a291|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::waiting_AllocateMtpResourceReq - (capCount,region),A(1,BOS_REG),B(2,UCCX_REG), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x129, passthru=0, resourceCount=1|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- DeviceName=XC-BOY02VOIPRT1 Ci=89950016 ResourceCount=1|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- Logging RegionA=BOS_REG Caps and MTP/XCoder Region=BOS_REG Caps|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- Device Caps = 6 |5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=8|*^*^*
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- Logging RegionB=UCCX_REG Caps and MTP/XCoder Region=BOS_REG Caps|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- Device Caps = 4 2 |5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- match1=0 match2=2|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::getResourcesAllocated -- allocateErrBitset=0x20|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaTerminationPointControl(13)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=89950016, errBitset=0x24|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::resource_rsvp_AllocateMtpResourceErr Device=XC-BOY02VOIPRT1 deviceCapIntersec=0|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::adjustDeviceTblXcoder - mCepn=a3090f65-b772-c7e0-711b-4c089697a291, allocateErrBitset=0x24, devCapIntersect=0x0, mandatoryCaps=0x0, resourceCount=1|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.228 |MediaResourceCdpc(463200)::adjustDeviceTblXcoder - Codec Mismatch
Thus, sending a Reorder tone to the phone because of the codec mismatch.
14:17:15.231 |StationD: (0218199) StartTone tone=37(ReorderTone), direction=0.|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
14:17:15.231 |StationD: (0218199) SelectSoftKeys instance=1 reference=89949961 softKeySetIndex=8 validKeyMask=fffeffff.|5,100,50,1.246380859^10.4.19.38^SEP00269943C946
TAC thought I might be hitting a firmware bug CSCtq97254 so I upgrade one of the phones to version 9.2.3, now if I disable G722 everything works fine but if G722 is enabled I get the same issue.
Here are traces before and after the phone is upgraded
I went through the traces collected for the calls before and after the firmware upgrade.
For the failed call (even after the firmware upgrade), I see no difference in the signaling. The phone still advertises only 1 codec (i.e. G722) as a part of its capabilities set because of which the call fails.
13:25:55.344 |MediaTerminationPointControl(13)::waiting_AllocateMtpResourceReq - (capCount,region),A(1,BOS_REG),B(2,UCCX_REG), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x129, passthru=0, resourceCount=1|3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::getResourcesAllocated -- DeviceName=XC-BOY02VOIPRT1 Ci=90803317 ResourceCount=1|3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::getResourcesAllocated -- Logging RegionA=BOS_REG Caps and MTP/XCoder Region=BOS_REG Caps|3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- Device Caps = 6 |3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=8|*^*^*
13:25:55.344 |MediaTerminationPointControl(13)::getResourcesAllocated -- Logging RegionB=UCCX_REG Caps and MTP/XCoder Region=BOS_REG Caps|3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |MediaTerminationPointControl(13)::logCapabilitiesinTrace -- Device Caps = 4 2 |3,200,17,1.3673515^10.40.168.53^CTI_2415
13:25:55.344 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
13:25:55.344 |MediaTerminationPointControl(13)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|3,200,17,1.3673515^10.40.168.53^CTI_2415
However, for a working call (with the previous firmware version), I see that the phone advertises G711ulaw, G711alaw and G722 (along with others) as a part of its capabilities set.
077410377 |2012/07/13 13:27:37.381 |100 |SdlSig |MediaExchangeAgenaUpdateCapabilities |waitForStationCapabilities |AgenaInterface(5,100,216,1677583) |StationCdpc(5,100,52,2342539) |3,200,17,1.3673807^10.40.168.53^CTI_2432 |[R:N-H:0,N:3,L:1,V:0,Z:0,D:0] AudioCapCount=12(25,40)(6,60)(7,60)(8,60)(4,40)(2,40)(86,60)(15,60)(16,60)(11,60)(12,60)(257,1) CryptoAudioCapCount0 VideoCapCount=0 CryptoVidCount0 AudioCapDir=0 VideoCapDir=0 DataCapDir=0 ipAddrType=0 ipv4=10.4.19.38 Supp.Payload RFC[0 0 0 0 0 ] CustomPictureFormatCount=0 PortInfoList [ confID=0 callRefID=0]
So, it appears that even after the upgrade, the phone doesn’t advertise all the codecs. As you mentioned that disabling the Advertise G722 codec makes the call to work, I would be really interested to know the difference for this instance.
