Call ring agent phone and drop within 1 second .

kelvinteh15 · ‎06-07-2016

Hi,

Good Day.

We are running UCCX 9.0.2.11001-24 . There is a agent who have a intermittent problem where the phone ring but it will drop within 1 second before agent pickup the call . From the MIVR logs it show transfer interrupt but not able to identify if the issue is on the user end or UCCX end. Please advise if you know if there is away to find out the cause for this .

Call is from 5526 to 4740 (CTI route point) , hit the script and select agent 31209 . Ring 31209 one time and drop (within 1 second) .

Line 489: 17645492: May 26 10:51:50.313 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199, ConsultCallObserver RINGING

Line 490: 17645493: May 26 10:51:50.314 EST %MIVR-SS_TEL-7-UNK:Call.transferStarted(31209) JTAPICallContact[id=18266,implId=2071379/2,state=STATE_ANSWERED_IDX,inbound=true,App name=XXX_XX_XXXXXX,task=57000090199,session=41000016453,seq num=0,cn=4740,dn=4740,cgn=5526,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=4740,route=RP[num=4740],OrigProtocolCallRef=00000000001F9B5302F4412D00000000,DestProtocolCallRef=null,TP=12466]

Line 491: 17645494: May 26 10:51:50.314 EST %MIVR-SS_TEL-7-UNK:OrigCall=CallID:18266 MediaId:2071379/2 Task:57000090199, ConsultEvent= (P1-ccx_jtapi_1) 7128349/1 CallCtlConnAlertingEv 31209:P-CC-Admin:1 [#1167809] Cause:100 CallCtlCause:100 CiscoCause:31 FeatReason:12

Line 492: 17645495: May 26 10:51:50.314 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199 Got (P1-ccx_jtapi_1) 7128349/1 ConnAlertingEv 31209:P-CC-Admin:1 [#1167808] Cause:100 CallCtlCause:0 CiscoCause:31 FeatReason:12, (P1-ccx_jtapi_1) 7128349/1 CallCtlConnAlertingEv 31209:P-CC-Admin:1 [#1167809] Cause:100 CallCtlCause:100 CiscoCause:31 FeatReason:12, events on the AddressCallObserver.

Line 493: 17645496: May 26 10:51:50.314 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199 Got (P1-ccx_jtapi_1) 7128349/1 ConnInProgressEv 31209:P-CC-Admin:1 [#1167806] Cause:100 CallCtlCause:0 CiscoCause:31 FeatReason:12, (P1-ccx_jtapi_1) 7128349/1 CallCtlConnOfferedEv 31209:P-CC-Admin:1 [#1167807] Cause:100 CallCtlCause:-1 CiscoCause:31 FeatReason:12, events on the AddressCallObserver.

Line 790: 17645753: May 26 10:51:51.934 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199 gets TermConnDroppedEv, meta code:132, cause code:100

Line 791: 17645754: May 26 10:51:51.934 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199, TerminalConnection to Terminal: CTI_12466 is DROPPED, 2071379/2

Line 793: 17645756: May 26 10:51:51.934 EST %MIVR-SS_TEL-7-UNK:Call.abandoned() JTAPICallContact[id=18266,implId=2071379/2,state=STATE_ABANDONED_IDX,inbound=true,App name=XXX_XX_XXXXXX,task=57000090199,session=41000016453,seq num=0,cn=4740,dn=4740,cgn=5526,ani=null,dnis=null,clid=null,atype=DIRECT,lrd=null,ocn=4740,route=RP[num=4740],OrigProtocolCallRef=00000000001F9B5302F4412D00000000,DestProtocolCallRef=null,TP=12466]

Line 794: 17645757: May 26 10:51:51.936 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199, transfer interrupted, com.cisco.app.impl.ContactInactiveInterruption: Contact id: 18266, Contact terminated remotely

Line 795: 17645758: May 26 10:51:51.936 EST %MIVR-SS_TEL-7-UNK:OrigCall=CallID:18266 MediaId:2071379/2 Task:57000090199, ConsultEvent= (P1-ccx_jtapi_1) 7128349/1 CallObservationEndedEv [#1167874] Cause:100 CallCtlCause:0 CiscoCause:0 FeatReason:12

Line 796: 17645759: May 26 10:51:51.936 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199, ConsultCallObserver():Received msg from original call Interrupted

Line 797: 17645760: May 26 10:51:51.940 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199, released TP[type=Cisco CTI Port,id=24,implId=12466,active=false,state=IDLE] from 4740, and releasing udpPort 28218

Line 798: 17645761: May 26 10:51:51.940 EST %MIVR-SS_TEL-7-UNK:CallID:18266 MediaId:2071379/2 Task:57000090199 com.cisco.jtapi.TermObservationEndedEvImpl received

Line 6880: 17651648: May 26 10:51:56.863 EST %MIVR-SS_RM-7-UNK:Task: 57000090199 canceled setting ResourceUnAvailableInterruption

Line 6924: 17651692: May 26 10:51:56.937 EST %MIVR-LIB_EVENT-5-TOO_LONG_IN_QUEUE:Event queue time exceeded: Event=com.cisco.call.CallEvent[CALL_DISCONNECTED,state=CALL_DISCONNECTED,isRemote=true,task=AppTask[id=0xd45785a57,time=1464223901511,state=ABORTED,exception=com.cisco.contact.ContactInactiveException: Contact id: 18266, Channel id: 24, Contact is in Terminated/Connected state,active=false,aborting=com.cisco.contact.ContactInactiveException: Contact id: 18266, Channel id: 24, Contact is in Terminated/Connected state,app=App[name=XXX_XX_XXXXXX,type=Cisco Script Application,id=64,desc=XXX_XX_XXXXXXS,enabled=true,max=60,valid=true,cfg=[ApplicationConfig[schema=ApplicationConfig,time=2015-07-15 14:41:31.0,recordId=186,desc=XXX_XX_XXXXXXS,name=XXX_XX_XXXXXX,type=Cisco Script Application,id=64,enabled=true,sessions=60,script=SCRIPT[XXXXXX.aef],defaultScript=,vars=[],defaultVars=null]]],trigger=ContactApplicationTrigger[time=1464223901511,locale=en_AU,cfg=JTAPITriggerConfig[schema=ApplicationTr...

Line 6924: 17651692: May 26 10:51:56.937 EST %MIVR-LIB_EVENT-5-TOO_LONG_IN_QUEUE:Event queue time exceeded: Event=com.cisco.call.CallEvent[CALL_DISCONNECTED,state=CALL_DISCONNECTED,isRemote=true,task=AppTask[id=0xd45785a57,time=1464223901511,state=ABORTED,exception=com.cisco.contact.ContactInactiveException: Contact id: 18266, Channel id: 24, Contact is in Terminated/Connected state,active=false,aborting=com.cisco.contact.ContactInactiveException: Contact id: 18266, Channel id: 24, Contact is in Terminated/Connected state,app=App[name=XXX_XX_XXXXXX,type=Cisco Script Application,id=64,desc=XXX_XX_XXXXXXS,enabled=true,max=60,valid=true,cfg=[ApplicationConfig[schema=ApplicationConfig,time=2015-07-15 14:41:31.0,recordId=186,desc=XXX_XX_XXXXXXS,name=XXX_XX_XXXXXX,type=Cisco Script Application,id=64,enabled=true,sessions=60,script=SCRIPT[XXXXXX.aef],defaultScript=,vars=[],defaultVars=null]]],trigger=ContactApplicationTrigger[time=1464223901511,locale=en_AU,cfg=JTAPITriggerConfig[schema=ApplicationT

Thanks.

Best regards,

kelvin

Tristan Cober · ‎06-08-2016

CUCM CM and CTI traces would be the next steps.

kelvinteh15 · ‎06-08-2016

[toc:faq]

Not much in the call logs show .

2016/05/26 10:51:50.158|CC|SETUP|49561913|49561914|12466|31209|31209

2016/05/26 10:51:50.162|CC|OFFERED|49561913|49561914|12466|31209|31209|CTI_12466|SEPD824BD26EB39

2016/05/26 10:51:50.162|SIPL|49561914|TCP|OUT|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,1.12869168^*^*|57392202|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|INVITE

2016/05/26 10:51:50.196|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|5060|2,100,13,62.4882023^172.16.30.53^*|57392203|1319200-7461489d-55e00d-351e10ac@172.16.30.53|100 Trying
2016/05/26 10:51:50.214|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|5060|2,100,13,62.4882024^172.16.30.53^*|57392204|1319200-7461489d-55e00d-351e10ac@172.16.30.53|200 OK
2016/05/26 10:51:50.217|SIPL|49561914|TCP|IN|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,774447.339^192.168.159.18^*|57392205|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|100 Trying
2016/05/26 10:51:50.223|SIPT|49561898|TCP|OUT|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|5060|2,100,13,1.12869169^*^*|57392206|1319200-7461489d-55e00d-351e10ac@172.16.30.53|ACK

2016/05/26 10:51:50.303|SIPL|49561914|TCP|IN|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,774447.340^192.168.159.18^*|57392207|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|180 Ringing

2016/05/26 10:51:50.729|CC|SPLIT|49561794|49561818
2016/05/26 10:51:50.735|CC|SPLIT|49561910|49561911
2016/05/26 10:51:50.737|CC|JOIN|49561794|49561911
2016/05/26 10:51:50.740|CC|RELEASE|49561818|0|0

2016/05/26 10:51:50.740|CC|RELEASE|49561910|0|0

2016/05/26 10:51:51.925|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883985^172.16.30.53^*|57392211|1319200-7461489d-55e00d-351e10ac@172.16.30.53|BYE

2016/05/26 10:51:51.929|CC|RELEASE|49561898|49561901|16

2016/05/26 10:51:51.931|SIPT|49561898|TCP|OUT|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883985^172.16.30.53^*|57392212|1319200-7461489d-55e00d-351e10ac@172.16.30.53|200 OK
2016/05/26 10:51:51.931|SIPT|49561898|TCP|OUT|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|5060|2,100,13,38.2883985^172.16.30.53^*|57392213|1319200-7461489d-55e00d-351e10ac@172.16.30.53|SUBSCRIBE
2016/05/26 10:51:51.932|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883986^172.16.30.53^*|57392214|1319200-7461489d-55e00d-351e10ac@172.16.30.53|NOTIFY
2016/05/26 10:51:51.933|SIPT|49561898|TCP|OUT|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883986^172.16.30.53^*|57392216|1319200-7461489d-55e00d-351e10ac@172.16.30.53|200 OK
2016/05/26 10:51:51.933|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|5060|2,100,13,62.4882025^172.16.30.53^*|57392215|1319200-7461489d-55e00d-351e10ac@172.16.30.53|200 OK
2016/05/26 10:51:51.933|SIPT|49561898|TCP|IN|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883987^172.16.30.53^*|57392217|1319200-7461489d-55e00d-351e10ac@172.16.30.53|NOTIFY
2016/05/26 10:51:51.934|SIPT|49561898|TCP|OUT|172.16.29.50|5060|XXX-XXX-XXX-XX_TRUNK|172.16.30.53|36983|2,100,13,38.2883987^172.16.30.53^*|57392218|1319200-7461489d-55e00d-351e10ac@172.16.30.53|481 Subscription does not exist

2016/05/26 10:51:51.935|SIPL|49561914|TCP|OUT|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,200,13,70.67535^172.16.30.57^CTI_12466|57392219|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|CANCEL
2016/05/26 10:51:51.985|SIPL|49561914|TCP|IN|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,774447.341^192.168.159.18^*|57392220|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|200 OK

2016/05/26 10:51:51.987|CC|RELEASE|49561913|49561914|16

2016/05/26 10:51:52.032|SIPL|49561914|TCP|IN|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,774447.342^192.168.159.18^*|57392221|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|487 Request Cancelled

2016/05/26 10:51:52.032|SIPL|49561914|TCP|OUT|172.16.29.50|5060|SEPD824BD26EB39|192.168.159.18|51295|2,100,13,774447.342^192.168.159.18^*|57392222|68edc80-746148a6-24d7ff-321d10ac@172.16.29.50|ACK

Deepak Mehta · ‎06-08-2016

HI Kelvin,

It doesn't look you have tracing set to detailed level,please enable detailed traces level on CUCM .

Also i would suggest to have transcoder applied to the DP of the CTI port just to ensure it is not a codec mismatch.

kelvinteh15 · ‎06-08-2016

Thanks Deepak,

We don't have the transcoder in the DP . Only the Software MTP (callmanager) in it . I going to have user to directly call the agent and verify have any issue.

Deepak Rawat · ‎06-08-2016

Can you please make sure this agent does not have any unsupported configuration such as Idivert key, call forwarding etc.

Regards

Deepak

kelvinteh15 · ‎06-08-2016

Hi Deepak,

Do you mean if the phone have softkey of IDivert or call forwarding ? Or you are referring to if the agent turn on the forward during the time it have the drop call ?

Nelson Alonso · ‎07-16-2020

Hi, I am facing the same issue. Were you able to figure out what was causing this issue? Thanks

Ahmed Khalefa · ‎06-09-2016

Hello Kelvin,

From above logs , the call seems to be disconnected from the source 5526 ..
not much info , does this issue happen with same agent 31209 always ? .. also , does it happen from specific sources ? .. ( internal , external .. )

Thanks A lot,
Ahmed Salah