Introducción

Este documento describe los problemas comunes que se observan en MediaSense (MS) y que causan la pérdida de grabaciones o que no se pueden reproducir en el servidor.

  

Prerequisites

Requirements

Cisco recomienda que tenga los conocimientos necesarios sobre estos temas:

• MS de Cisco
• Cisco Unified Contact Center Express (UCCX)
• Cisco Unified Communications Manager (CUCM)

Componentes Utilizados

La información que contiene este documento se basa en las siguientes versiones de software y hardware.

• MS 10.5 y posterior
• Call Manager 11.0

La información de este documento se creó a partir de los dispositivos de un entorno de producción específico. Todos los dispositivos que se utilizan en este documento se pusieron en funcionamiento con una configuración verificada (predeterminada). Si tiene una red en vivo, asegúrese de entender el posible impacto de cualquier comando.

Antecedentes

Uno de los problemas más comunes que se encuentran en MS es que no puede acceder a las grabaciones porque los medios se eliminan de MS. Este documento explica cómo resolver mejor estos tipos de escenarios para ayudar a entender por qué los medios grabados no están en MS.

Problema

No puede reproducir grabaciones de MS Search and Play. El tamaño de la pista muestra 00:00:00 y hay un signo de exclamación amarillo a la izquierda de la grabación que indica que no hay medios como se muestra en la imagen.

Problemas más comunes

Medios recortados

La configuración de recorte de MS puede eliminar las grabaciones si han pasado una determinada antigüedad o si se necesita más espacio en disco para las grabaciones más recientes.

Puede encontrar la configuración de recorte en esta ubicación: Cisco MediaSense Administration > Administration > Prune Policy Configuration. Si la opción No eliminar automáticamente los datos asociados y los archivos de medios convertidos está seleccionada, cuando las grabaciones se recortan del servidor, sus metadatos permanecen y se muestra un signo de exclamación amarillo con un error "Registro cancelado" o "Pistas de tamaño cero" como se muestra en la imagen.

La forma más rápida de verificarlo es con groom.log generado por el servicio de medios.

Poda para la edad

Puede recopilar el archivo groom.log y/o orapuru.log de la recopilación de registros del servicio multimedia desde la herramienta de supervisión en tiempo real (RTMT), o bien puede utilizar rápidamente la interfaz de línea de comandos (CLI):

Nota: El registro del novio muestra el archivo SMD sin procesar, que está asociado con el ID de sesión de la base de datos MySQL del servicio de medios. Es engorroso para obtener un ID de sesión de un archivo SMD cuando toma el acceso raíz al servidor. Estos registros solo son buenos para comprender la antigüedad de las grabaciones recortadas.

Por ejemplo, estos registros muestran que las grabaciones del 4 de enero de 2017 se recortan:

admin:file view activelog /ora/logs/media/groom.log
|2017-01-05 15:04:37.169| 10093: RUNNING min 86400 secs max 1 days evtmax 1 days
|2017-01-05 15:04:37.169| RETENTION groom /recordedMedia/10093/20170104/586d4513.smd
|2017-01-05 15:04:37.172| RETENTION groom /recordedMedia/10093/20170104/586d463f.smd
|2017-01-05 15:04:37.190| PRUNED DB config before Wed Jan 4 16:11:49 2017
 
|2017-01-05 15:04:37.252| 10198: RUNNING min 86400 secs max 1 days evtmax 1 days
|2017-01-05 15:04:37.252| RETENTION groom /recordedMedia/10198/20170104/586d45e8.smd
|2017-01-05 15:04:37.272| PRUNED DB config before Wed Jan 4 16:07:41 2017
 
|2017-01-05 15:04:37.291| 10055: RUNNING min 86400 secs max 1 days evtmax 1 days
|2017-01-05 15:04:37.291| RETENTION groom /recordedMedia/10055/20170104/586d4632.smd
|2017-01-05 15:04:37.311| PRUNED DB config before Wed Jan 4 16:10:05 2017

orapurge.logmuestra un poco más de detalle a medida que se presentan el ID de sesión y los números de seguimiento:

admin: file view activelog /ora/logs/media/orapurge.log
2017-01-10 14:50:26.551 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:71> ] OraSessionPurge purging begins...
2017-01-10 14:50:27.189 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:106> ] Recording id 10000 first time 1483988829 (5873df5d)
2017-01-10 14:50:27.190 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:114> ] Found 0 clips below requested time
2017-01-10 14:50:27.190 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:106> ] Recording id 10001 first time 1483993518 (5873f1ae)
2017-01-10 14:50:27.191 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:114> ] Found 1 clips below requested time
2017-01-10 14:50:27.193 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:142> ] ORA session 56e21598489cf631-TRACK0 has been groomed and is now removed

Ejemplo de análisis de registro para realizar un seguimiento de la reducción de grabaciones por antigüedad

En este ejemplo, verá que las grabaciones se han recortado mucho más rápido que la configuración de 90 recortes.

En los registros ORA-ora, se ve que la grabación con la ID de sesión 56e5159848cca971, entró en MS correctamente y se cerró con un estado CLOSED_NORMAL.

La grabación comenzó a la hora de la época 1483987536761, que es 'Lun 9 Ene 13:45:36 2017 GMT-5:00'.

También verá la URL de medios aquí, que muestra una grabación guardada.

0005394466: 10.45.2.17: Jan 10 2017 14:58:09.955 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-8} Result from the command - 
{"responseMessage":"Success: Your request was successfully completed.","responseCode":2000,"responseBody":... (removed for brevity)

{"sessionState":"CLOSED_NORMAL","callControllerType":"Cisco-CUCM","sessionId":"56e5159848cca971","urls":{"httpUrl":"https://10.45.2.17:8446/recordedMedia/oramedia/mp4/56e5159848cca971.mp4","rtspUrl":"rtsp://10.45.2.17/archive/56e5159848cca971","mp4Url":"https://10.45.2.17:8446/recordedMedia/oramedia/mp4/56e5159848cca971.mp4","wavUrl":"https://10.45.2.17:8446/recordedMedia/oramedia/wav/56e5159848cca971.wav"},"sessionStartDate":1483987536761,"tracks":[{"trackStartDate":1483987536761,"trackDuration":166256,"codec":"PCMU","downloadUrl":"https://10.45.2.17:8446/mma/ExportRaw?recording=56e5159848cca971-TRACK1","trackNumber":1,"trackMediaType":"AUDIO","participants":[{"participantStartDate":1483987536761,"deviceRef":"7876050871","isConference":false,"xRefCi":"40461072","participantDuration":166256,"deviceId":"DOM-WAN-RT1"}]},{"trackStartDate":1483987536761,"trackDuration":166256,"codec":"PCMU","downloadUrl":"https://10.45.2.17:8446/mma/ExportRaw?recording=56e5159848cca971-TRACK0","trackNumber":0,"trackMediaType":"AUDIO","participants":[{"participantStartDate":1483987536761,"deviceRef":"3204","lineDisplayName":"SIN ASIGNAR AREA CAJA","isConference":false,"xRefCi":"18891730","participantDuration":166256,"deviceId":"SEP00CCFC16F00D"}]}],"sessionDuration":166256,"callControllerIP":"10.64.0.12"}

Verá que esta grabación se purga en el archivo orapuru.log. Track1 y Track0 son para las partes independientes de la grabación:

  

2017-01-10 15:00:26.539 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:71> ] OraSessionPurge purging begins...
2017-01-10 15:00:27.205 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:106> ] Recording id 10000 first time 1483988829 (5873df5d)
2017-01-10 15:00:27.205 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:114> ] Found 0 clips below requested time
2017-01-10 15:00:27.206 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:106> ] Recording id 10001 first time 1483993518 (5873f1ae)
...
2017-01-10 15:00:27.239 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:106> ] Recording id 10043 first time 1483994599 (5873f5e7)
2017-01-10 15:00:27.239 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:114> ] Found 1 clips below requested time
2017-01-10 15:00:27.242 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurge.cpp:142> ] ORA session 56e5159848cca971-TRACK1 has been groomed and is now removed
...
2017-01-10 15:00:27.464 [ OraSessionPurge(19409) ORA_PURGE=1 <OraSessionPurgep.cpp:193> ] OraSessionPurge purging completes.

Los logs ORA-ora nos muestran las sesiones que se recortan, incluye la sesión previamente mostrada:

0005395238: 10.45.2.17: Jan 10 2017 15:02:47.745 -0400: %CCBU_API-6-PRUNE_SESSIONS_COMMAND: {Thrd=AMS-pool-1-thread-10} %[message=(Prune id = ORA.11.0.1.10000-103.ReplyTo.1.MMA.MMA1-1484074962694-1, # sessions = 6)]: Response to Prune Sessions Command 
0005395239: 10.45.2.17: Jan 10 2017 15:02:47.746 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-10} deletePrunedSessions(Operation Id: 1386, # sessions: 6) begin transaction duration : 0 
0005395240: 10.45.2.17: Jan 10 2017 15:02:47.813 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-10} deletePrunedSessions(Operation Id: 1386, # sessions: 6) commit duration : 37 
0005395241: 10.45.2.17: Jan 10 2017 15:02:47.813 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-10} deletePrunedSessions(Operation Id: 1386, # sessions: 6) transaction duration : 66 
0005395242: 10.45.2.17: Jan 10 2017 15:02:47.813 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-10} deletePrunedSessions(Operation Id: 1386, # sessions: 6) method duration : 67 
0005395243: 10.45.2.17: Jan 10 2017 15:02:47.813 -0400: %CCBU_API-7-TRACE: {Thrd=AMS-pool-1-thread-10} deletePrunedSessions(Operation Id: 1386, # sessions: 6) deletable sessions: 6, deleted sessions: 6

Esto muestra las 6 sesiones recortadas:

0005395244: 10.45.2.17: Jan 10 2017 15:02:47.813 -0400: %CCBU_API-6-PRUNE_SESSIONS_RESPONSE: {Thrd=AMS-pool-1-thread-10} %[message=PruneSessionsResponse[Response,prune.id=ORA.11.0.1.10000-103.ReplyTo.1.MMA.MMA1-1484074962694-1,status=SUCCESS,sessions(6)=[56e5159848cca971, 56e6159848cedb61, 56e7159848ddf241, 56e8159848de26c1, 56e91598490f5bd1, 56ea1598493582c1],seqnum=2780,header=MessageHeader[jmsType=ORA.AMS.PruneSessionsResponse,id=null,corrId=null,ssId=API1,ssType=API,dest=ORA.11.0.1.10000-103.ReplyTo.1.MMA.MMA1,replyTo=null,kind=RESPONSE,reqId=MMA.MMA1.1484074967738.1654,reqTimeout=180000,alwaysDeliverResponses=true,msgVersion=[1, 1, 1],timestamps={created=1484074967813}],state=CREATED,sequenced=false,msg={null}]]: Response to Prune Sessions Response
 

Poda para el espacio

También puede ver cuándo se recortan las grabaciones para recuperar espacio en disco para las nuevas grabaciones. Cuando un MS alcanza la condición crítica de la partición /registeredMedia alcanzando el 90 por ciento, las grabaciones más antiguas (incluso si son más jóvenes que el umbral de edad) se recortan para hacer espacio para las nuevas. MS recorta los lotes de 200 grabaciones hasta que el espacio en disco sea igual o inferior al 86%.

admin:file view activelog /ora/logs/media/groom.log
|2016-10-03 16:09:51.669| Volume /recordedMedia OVERSUBSCRIBED at 87%, need to get to 86%
|2016-10-03 16:09:51.669| Attempting 0 of max attempts[ 20 ]
|2016-10-03 16:09:54.729| OVERSUBSCRIPTION groom /recordedMedia/10054/20160902/57c9d313.smd
|2016-10-03 16:09:54.730| OVERSUBSCRIPTION groom /recordedMedia/10068/20160902/57c9d313.smd
|2016-10-03 16:09:54.734| OVERSUBSCRIPTION groom /recordedMedia/10073/20160902/57c9d314.smd
|2016-10-03 16:09:54.734| OVERSUBSCRIPTION groom /recordedMedia/10092/20160902/57c9d314.smd

Poda antes del archivado

El archivado de grabaciones en un servidor SFTP se introdujo en MS 10.5. En algunos casos, puede realizar el recorte de medios antes de que se realice el archivado. Un problema común es que la conectividad con el servidor SFTP deja de funcionar, y mientras que la grabación se ha archivado con mucho tiempo de antelación, MS no puede hacerlo debido a problemas de conexión con el servidor SFTP. MediaSense intenta archivar repetidamente una grabación si se produce un error al intentar archivarla.

A continuación se muestra un ejemplo de lo que verá en /var/log/active/ora/logs/storagemanagement/ORA-storagemanagementagent.YYY-MM-DDTHH-MM-SS.sss.log:

admin: file view activelog /ora/logs/media/storagemanagement/ORA-storagemanagementagent.YYY-MM-DDTHH-MM-SS.sss.log

ID de sesión archivada: ebcf45708f010bc1
IP del servidor SFTP: 10.75.41.225

MS convierte la grabación a MP4 para archivarla:

0010755845: 10.75.41.210: Sep 08 2016 20:33:09.068 -0500: %CCBU_MMA-6-CONVERT_SESSION_REQUEST: {Thrd=pool-14-thread-107845} 
%[message_string=ConvertSessionTask-185682: Sending response ConvertSessionResponse[Response,session=ebcf45708f010bc1,
status=SUCCESS,url=http://10.75.41.210:8081/recordedMedia/oramedia/mp4/ebcf45708f010bc1.mp4,details=Success,seqnum=1528709,
header=MessageHeader[jmsType=ORA.MMA.ConvertSessionResponse,id=null,corrId=null,ssId=MMA1,
ssType=MMA,dest=ORA.10.5.1.10000-23.ReplyTo.1.AMS.API1,replyTo=null,kind=RESPONSE,reqId=API.API1.1473384786428.476820,
reqTimeout=7200000,alwaysDeliverResponses=false,msgVersion=[1, 1, 1],timestamps={created=1473384789060}],
state=CREATED,sequenced=false,msg={null}]]: 

MS procesa una solicitud para transferir la grabación:

0010755846: 10.75.41.210: Sep 08 2016 20:33:09.073 -0500: %CCBU_MMA-6-MSG_INCOMING_FROM_BUS: {Thrd=ActiveMQ Session Task-2315}
 %[correlation_id=null][mid=ID:TacMS-60118-1471342398443-3:3:2:1:477533][msg_kind=ActiveMQMapMessage][
msg_type=ORA.MMA.TransferSessionRequest]: A message has been received by the message bus 

0010755847: 10.75.41.210: Sep 08 2016 20:33:09.074 -0500: %CCBU_MMA-6-TRANSFER_SESSION_EVENT_INFO: {
Thrd=pool-1-thread-20-MMA1-1409831} %[event.type=Adding to execute TransferSessionTask-291323, sessionName=ebcf45708f010bc1: ]
[message=]: TransferSession

MS intenta conectarse al servidor SFTP, pero se produce un error con una excepción de Java Secure Channel (JSch). JSch es una implementación Java de SSHv2 que MS utiliza para su cliente SSH:

0010755848: 10.75.41.210: Sep 08 2016 20:33:09.074 -0500: %CCBU_MMA-6-TRANSFER_SESSION_EVENT_INFO: {Thrd=pool-1-thread-8-MMA1-1409832} 
%[event.type=SFTP Trace Level (1) - Connecting to 10.75.41.225 port 22][message=]: TransferSession 

0010755849: 10.75.41.210: Sep 08 2016 20:33:09.076 -0500: %CCBU_MMA-3-CONVERT_SESSION_ERROR: 
{Thrd=pool-1-thread-8-MMA1-1409832} %[exception=][message=TransferSessionTask-291323, sessionName=ebcf45708f010bc1: 
Exception][message_string=com.jcraft.jsch.JSchException: java.net.ConnectException: Connection refused]: 

0010755850: 10.75.41.210: Sep 08 2016 20:33:09.076 -0500: %CCBU_MMA-3-EXCEPTION_INFO: {Thrd=pool-1-thread-8-MMA1-1409832} 
%[build_date=Jan 16, 1970 11:38 PM][build_type=rel][exception=com.jcraft.jsch.JSchException: 
java.net.ConnectException: Connection refused
 at com.jcraft.jsch.Util.createSocket(Util.java:349)
 at com.jcraft.jsch.Session.connect(Session.java:215)
 at com.jcraft.jsch.Session.connect(Session.java:183)
 at com.cisco.ora.mediamanageragent.msgs.TransferSessionTask.createSftpSession(TransferSessionTask.java:479)
 at com.cisco.ora.mediamanageragent.msgs.TransferSessionTask.fileExists(TransferSessionTask.java:417)
 at com.cisco.ora.mediamanageragent.msgs.TransferSessionTask.getAction(TransferSessionTask.java:121)
 at com.cisco.ora.mediamanageragent.msgs.TransferSessionTask.run(TransferSessionTask.java:203)
 at com.cisco.ccbu.infra.threads.InstrumentedRunnable.run(InstrumentedRunnable.java:92)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:662)
 at com.cisco.ccbu.infra.threads.ThreadPoolThread.run(ThreadPoolThread.java:164)
Caused by: java.net.ConnectException: Connection refused
 at java.net.PlainSocketImpl.socketConnect(Native Method)
 at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
 at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
 at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
 at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
 at java.net.Socket.connect(Socket.java:529)
 at java.net.Socket.connect(Socket.java:478)
 at java.net.Socket.<init>(Socket.java:375)
 at java.net.Socket.<init>(Socket.java:189)
 at com.jcraft.jsch.Util.createSocket(Util.java:343)
 ... 11 more

Falla de negociación de códec de CUCM

Este ejemplo es con grabación en puente incorporado (BiB). En el vocabulario de CUCM/MS, el dispositivo de extremo cercano es el dispositivo que transmite el audio a MS; se trata de un teléfono de CUCM en el caso del teléfono configurado con grabación BiB. El dispositivo de extremo lejano es el dispositivo que transmite medios al dispositivo grabado. En la mayoría de los casos, se trata de un troncal SIP de CUCM, que es el dispositivo del que procede la señalización SIP de un teléfono PSTN. De manera equivalente, puede pensar en la señalización de extremo cercano que transmite el dispositivo grabado y la señalización de extremo lejano que se recibe del dispositivo grabado.

En este ejemplo, esta es la información de llamada que puede ver en MS Search and Play:

Session ID: 745a15454b0e7f62 
ERROR: Record Response Fail 11/11/2016 10:40 GMT-08:00
Calling: 5255553333 xrefCI: 71234316   Codec Listed: G729
Called : 555666       xrefCI: 71233302   Codec Listed: none

Verá que es probable que se haya producido un error de negociación de códec en la llamada de extremo cercano desde el teléfono CUCM al troncal MS SIP. xrefCI que se ven son los CUCM CI para la llamada real y no para la llamada grabada por MS.

These two CIs comprises one SIP Call-ID for the audio call between the two phones.
DN: 5255553333 <-- CI: 71234316 --> CUCM <-- CI: 71233302 --> DN: 555666

En los registros de CUCM, estos son los CI que se encuentran para que se registre la llamada:

These two CIs comprise one SIP Call-ID for the near-end recorded call.
DN: 555666 <-- CI: 71233611 --> CUCM <-- CI: 71233612 --> MS SIP Trunk 'DN': 4321

These two CIs comprise one SIP Call-ID for the far-end recorded call.
DN: 5255553333 <-- CI: 71233614 --> CUCM <-- CI: 71233615 --> MS SIP Trunk 'DN': 4321

Registros de MS

Llamada de extremo cercano:

First Invite MS recibe: Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60 desde el dispositivo de extremo cercano.

0000724480: 10.55.100.23: Nov 11 2016 12:40:29.637 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-sip-thread-17475} %[message_string=process new Invitation: SipCall-17502, INBOUND_RECORDING, null, State=ALERTED: , processing=7
INVITE sip:4321@10.55.100.23:5060 SIP/2.0
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee04b9db528
Max-Forwards: 69
To: <sip:4321@10.55.100.23>
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 101 INVITE
Content-Length: 0
Date: Fri, 11 Nov 2016 18:40:29 GMT
Supported: timer,resource-priority,replaces
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Min-SE: 1800
User-Agent: Cisco-CUCM11.0
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Expires: 180
Allow-Events: presence, kpml
Call-Info: <sip:10.1.1.60:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Session-ID: 00000000000000000000000000000000;remote=00000000000000000000000000000000
Cisco-Guid: 1346736640-0000065536-0000177089-0545324554
Session-Expires: 1800
P-Asserted-Identity: "(Operator) Jared TAC" <sip:555666@10.1.1.60>
Remote-Party-ID: "(Operator) Jared TAC" <sip:555666@10.1.1.60>;party=calling;screen=yes;privacy=off
Contact: <sip:555666@10.1.1.60:5060;transport=tcp>;isfocus

MS envía 180 Ringing.

0000724487: 10.55.100.23: Nov 11 2016 12:40:29.638 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-sip-thread-17475} %[message_string=postProcessInvitation SipCall-17502, INBOUND_RECORDING, NEAR_END, State=ALERTED: sending response
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee04b9db528
To: <sip:4321@10.55.100.23>;tag=ds23933dcf
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 101 INVITE
Content-Length: 0
Contact: <sip:4321@10.55.100.23:5060;transport=tcp>
Allow: INVITE, BYE, CANCEL, ACK, NOTIFY, INFO, UPDATE
Server: MediaSense/10.x

MS envía 200 OK con SDP.

0000724519: 10.55.100.23: Nov 11 2016 12:40:29.801 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-capture-thread-15474} %[message_string=SipCall-17502, INBOUND_RECORDING, NEAR_END, State=ALERTED send 200 Ok: 
SIP/2.0 200 Ok
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee04b9db528
To: <sip:4321@10.55.100.23>;tag=ds23933dcf
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 101 INVITE
Content-Length: 309
Contact: <sip:4321@10.55.100.23:5060;transport=tcp>
Content-Type: application/sdp
Allow: INVITE, BYE, CANCEL, ACK, NOTIFY, INFO, UPDATE
Server: MediaSense/10.x
v=0
o=CiscoORA 2153 1 IN IP4 10.55.100.23
s=SIP Call
c=IN IP4 10.55.100.23
t=0 0
m=audio 34370 RTP/AVP 102 0 8 9 18
a=rtpmap:102 MP4A-LATM/90000
a=fmtp:102 profile-level-id=24;object=23;bitrate=64000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=recvonly
]: Border Message

CUCM le proporciona una ACK para esta llamada sin SDP, lo que significa que CUCM no eligió un códec.

0000724529: 10.55.100.23: Nov 11 2016 12:40:29.868 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=DIALOG_CALLBACK.6} %[message_string=SipCall-17502, INBOUND_RECORDING, NEAR_END, State=ALERTED process ACK, hasBody=false
ACK sip:4321@10.55.100.23:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee4766a922
Max-Forwards: 69
To: <sip:4321@10.55.100.23>;tag=ds23933dcf
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 101 ACK
Content-Length: 0
Date: Fri, 11 Nov 2016 18:40:29 GMT
User-Agent: Cisco-CUCM11.0
Allow-Events: presence, kpml
Session-ID: 00000000000000000000000000000000;remote=59bbdbcfa64352fa65ba535ab3695142
]: Border Message

0000724530: 10.55.100.23: Nov 11 2016 12:40:29.868 -0600: %CCBU_CALL_CONTROL-7-TRACE: {Thrd=DIALOG_CALLBACK.11} -SdpParser: created AUDIO-MediaParameters: host=10.15.255.254, port=4000, RtpAttributes=[ payloadType=18 G729/8000 ], SENDONLY, pTime=20 
0000724531: 10.55.100.23: Nov 11 2016 12:40:29.868 -0600: %CCBU_CALL_CONTROL-4-WARN_MESSAGE: {Thrd=DIALOG_CALLBACK.6} %[message_string=SipCall-17502, INBOUND_RECORDING, NEAR_END, State=ALERTED invalid codec or does not have SDP body in Ack 

CUCM finaliza la llamada.

0000724562: 10.55.100.23: Nov 11 2016 12:40:29.871 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=DIALOG_CALLBACK.6} %[message_string=SipCall-17502, INBOUND_RECORDING, NEAR_END, State=DISCONNECTED sendBye, reason=reject sending 
BYE sip:555666@10.1.1.60:5060;transport=tcp SIP/2.0
Max-Forwards: 70
To: <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
From: <sip:4321@10.55.100.23>;tag=ds23933dcf
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 1 BYE
Content-Length: 0
]: Border Message

Llamada de extremo lejano:

La segunda invitación que recibe MS es: ID de llamada: 50459200-8261109d-125c83-2080fe0a@10.1.1.60 desde el dispositivo de extremo lejano.

  

INVITE sip:4321@10.55.100.23:5060;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee255dcfc0
Max-Forwards: 69
To: <sip:4321@10.254.128.36>
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-farend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695143~47718da5-fef5-1f81-1709-6f389f40258a-71233615
Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60
CSeq: 102 INVITE
Content-Length: 0
Date: Fri, 11 Nov 2016 18:40:29 GMT
Supported: timer,resource-priority,replaces
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Min-SE: 1800
User-Agent: Cisco-CUCM11.0
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Expires: 180
Allow-Events: presence, kpml
Call-Info: <sip:10.1.1.60:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Session-ID: 00000000000000000000000000000000;remote=00000000000000000000000000000000
Cisco-Guid: 1346736640-0000065536-0000177090-0545324554
Session-Expires: 1800
P-Asserted-Identity: "(Operator) Jared TAC" <sip:555666@10.1.1.60>
Remote-Party-ID: "(Operator) Jared TAC" <sip:555666@10.1.1.60>;party=calling;screen=yes;privacy=off
Contact: <sip:555666@10.1.1.60:5060;transport=tcp>;isfocus

MS envía 180 timbres para la segunda llamada.

0000724502: 10.55.100.23: Nov 11 2016 12:40:29.683 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-sip-thread-17476} %[message_string=postProcessInvitation SipCall-17503, INBOUND_RECORDING, NEAR_END, State=ALERTED: sending response
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee255dcfc0
To: <sip:4321@10.254.128.36>;tag=dsb56a3dfc
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-farend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695143~47718da5-fef5-1f81-1709-6f389f40258a-71233615
Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60
CSeq: 102 INVITE
Content-Length: 0
Contact: <sip:4321@10.55.100.23:5060;transport=tcp>
Allow: INVITE, BYE, CANCEL, ACK, NOTIFY, INFO, UPDATE
Server: MediaSense/10.x

MS envía 200 OK con SDP.

0000724516: 10.55.100.23: Nov 11 2016 12:40:29.800 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-capture-thread-15474} %[message_string=SipCall-17503, INBOUND_RECORDING, FAR_END, State=ALERTED send 200 Ok: 
SIP/2.0 200 Ok
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee255dcfc0
To: <sip:4321@10.254.128.36>;tag=dsb56a3dfc
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-farend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695143~47718da5-fef5-1f81-1709-6f389f40258a-71233615
Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60
CSeq: 102 INVITE
Content-Length: 309
Contact: <sip:4321@10.55.100.23:5060;transport=tcp>
Content-Type: application/sdp
Allow: INVITE, BYE, CANCEL, ACK, NOTIFY, INFO, UPDATE
Server: MediaSense/10.x
v=0
o=CiscoORA 2152 1 IN IP4 10.55.100.23
s=SIP Call
c=IN IP4 10.55.100.23
t=0 0
m=audio 53368 RTP/AVP 102 0 8 9 18
a=rtpmap:102 MP4A-LATM/90000
a=fmtp:102 profile-level-id=24;object=23;bitrate=64000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=recvonly
]: Border Message

CUCM envía ACK con SDP. Para este tramo de llamada, se elige G729, ya que ambos servidores lo admiten desde el SDP.

0000724521: 10.55.100.23: Nov 11 2016 12:40:29.866 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=DIALOG_CALLBACK.11} %[message_string=SipCall-17503, INBOUND_RECORDING, FAR_END, State=ALERTED process ACK, hasBody=true
ACK sip:4321@10.55.100.23:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee3220aa67f
Max-Forwards: 69
To: <sip:4321@10.254.128.36>;tag=dsb56a3dfc
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-farend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695143~47718da5-fef5-1f81-1709-6f389f40258a-71233615
Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60
CSeq: 102 ACK
Content-Length: 259
Date: Fri, 11 Nov 2016 18:40:29 GMT
User-Agent: Cisco-CUCM11.0
Allow-Events: presence, kpml
Session-ID: 00000000000000000000000000000000;remote=59bbdbcfa64352fa65ba535ab3695143
Content-Type: application/sdp
v=0
o=CiscoSystemsCCM-SIP 3695143 1 IN IP4 10.1.1.60
s=SIP Call
c=IN IP4 10.15.255.254
b=TIAS:8000
b=CT:8
b=AS:8
t=0 0
m=audio 4000 RTP/AVP 18 101
a=ptime:20
a=rtpmap:18 G729/8000
a=sendonly
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
]: Border Message

CUCM finaliza la llamada.

0000724546: 10.55.100.23: Nov 11 2016 12:40:29.869 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=DIALOG_CALLBACK.6} %[message_string=SipCall-17503, INBOUND_RECORDING, FAR_END, State=ACTIVE sendBye, reason=local disconnect sending 
BYE sip:555666@10.1.1.60:5060;transport=tcp SIP/2.0
Max-Forwards: 70
To: <sip:555666@10.1.1.60;x-farend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695143~47718da5-fef5-1f81-1709-6f389f40258a-71233615
From: <sip:4321@10.254.128.36>;tag=dsb56a3dfc
Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60
CSeq: 1 BYE
Content-Length: 0

MS registra la llamada como un error.

0000724557: 10.55.100.23: Nov 11 2016 12:40:29.871 -0600: %CCBU_CALL_CONTROL-7-TRACE: {Thrd=DIALOG_CALLBACK.6} -InMemoryDataBaseAdapter: processing UpdateLocalDB
Session: 745a15454b0e7f62, ERROR, MEDIA_SERVER_ERROR, sipServer=10.55.100.23, version=9, lastNotifiedVersion=9, fromDN=null, toDN=null, audioChannels=2, videoChannels=0, started: Fri Nov 11 12:40:29 CST 2016, ended: Fri Nov 11 12:40:29 CST 2016, duration=0sec, recordingServer=10.55.100.23, ccId=null, ccIp=10.1.1.60, type=PHONE, appType=null, ErrorDetail =MEDIA_SERVER_ERROR
CallEndPoint: type=NEAR_END, dn=555666, displayName=(Operator) Jared TAC, xRefci=71233302, device=SEP002497A964CF, conf=false, {SipCall-17502, INBOUND_RECORDING, NEAR_END, State=DISCONNECTED, CallId: 50459200-8261109d-125c82-2080fe0a@10.1.1.60}, Tracks=[TrackInfo: type=AUDIO, port=34370, trackNumber=0, repository=/recordedMedia, size=-1, state=ACTIVE, stateChanged=false, codec=null]
CallEndPoint: type=FAR_END, dn=5255553333, xRefci=71234316, device=10.15.255.254, conf=false, {SipCall-17503, INBOUND_RECORDING, FAR_END, State=DISCONNECTED, CallId: 50459200-8261109d-125c83-2080fe0a@10.1.1.60}, Tracks=[TrackInfo: type=AUDIO, port=53368, trackNumber=1, repository=/recordedMedia, size=-1, state=ACTIVE, stateChanged=false, codec=G729]

El archivo JSON se crea y se guarda en MS.

0000724560: 10.55.100.23: Nov 11 2016 12:40:29.871 -0600: %CCBU_CALL_CONTROL-6-BORDER_MESSAGE: {Thrd=Pool-ams-thread-9738} %[message_string=HttpPostClient-9738: executing POST http://10.55.100.23:8640/ora/SipAdaptorService/SipAdaptor/addOrUpdateSession HTTP/1.1
{"sessionData": {
"callControllerIP": "10.1.1.60",
"callControllerType": "Cisco-CUCM",
"endDate": 1478889629869,
"endPoints": [
{
"clusterid": "TACOp",
"conference": false,
"device": "SEP002497A964CF",
"displayName": "(Operator) Jared TAC",
"dn": "555666",
"startDate": 1478889629868,
"tracks": [{
"location": "/recordedMedia",
"mediaState": "ACTIVE",
"startDate": 1478889629868,
"track": 0,
"type": "AUDIO"
}],
"type": "NEAR_END",
"xRefci": "71233302"
},
{
"clusterid": "TACOp",
"conference": false,
"device": "10.15.255.254",
"dn": "5255553333",
"startDate": 1478889629868,
"tracks": [{
"codec": "G729",
"location": "/recordedMedia",
"mediaState": "ACTIVE",
"startDate": 1478889629868,
"track": 1,
"type": "AUDIO"
}],
"type": "FAR_END",
"xRefci": "71234316"
}
],
"errorDetail": "MEDIA_SERVER_ERROR",
"operationType": "ADD",
"recordingServer": "10.55.100.23",
"sessionName": "745a15454b0e7f62",
"sipServer": "10.55.100.23",
"startDate": 1478889629868,
"state": "ERROR",
"version": 9
}}]: Border Message
 

Registros de CUCM

Este es el análisis de dígitos para la BiB del teléfono CUCM que llama al patrón de marcado MS. b0042422044001 es el DN BiB.

47540157.011 |10:40:29.606 |AppInfo |Digit analysis: match(pi="1", fqcn="", cn="b0042422044001",plv="5", pss="Directory URI:Internal_pt:Voicemail_PT:UCCX_pt:SAT-TX-8-5-PT:SAT-TX-OffHrs-PT", TodFilteredPss="Directory URI:Internal_pt:Voicemail_PT:UCCX_pt:SAT-TX-8-5-PT", dd="4321",dac="0")
47540157.012 |10:40:29.606 |AppInfo |Digit analysis: analysis results
47540157.013 |10:40:29.606 |AppInfo ||PretransformCallingPartyNumber=b0042422044001
|CallingPartyNumber=b0042422044001
|DialingPartition=Internal_pt
|DialingPattern=4321

Respuesta de CUCM al análisis de dígitos. Este es el CI de la llamada: 71233611.

47540163.000 |10:40:29.606 |SdlSig |DmPidRes |wait |Da(4,100,214,1) |DeviceManager(4,100,208,1) |4,100,14,574746.28^10.1.1.60^Port 32978 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Cepn=c0132a35-e434-e61d-ddda-af59c7a2ce1d Id=3812252328 ccmType=3 DeviceName=MediaSense_RL Pid=4,100,90,41,

IC de BiB a CUCM: 71233611.

47540163.001 |10:40:29.606 |AppInfo |Digit analysis: wait_DmPidRes- Partition=[d15d1a00-02a2-34a7-e0d9-7d653b500c6d] Pattern=[4321] Where=[],cmDeviceType=[AccessDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=RouteListControl(4,100,90,41),CI=[71233611],Sender=Cdcc(4,100,222,745108)

Este CI está configurado con CI 71233612. Este es el CI para la conexión troncal SIP de CUCM-MS. Estos dos CI forman el ID de llamada SIP.

47540171.000 |10:40:29.606 |SdlSig |CcSetupReq |idle |RouteListControl(4,100,90,41) |Cdcc(4,100,222,745108) |4,100,14,574746.28^10.1.1.60^Port 32978 |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] CI=71233612 CI.branch=0 sBPL.plid=65 sBPL.l=0 sBPL.pl=5 sBPL.msd=0 FDataType=0 opId=0 ssType=0 SsKey=0 invokeId=0 resultExp=F bpda=F pi.piid=30 pi.l=0 pi2.piid=30 pi2.l=0 pi3.piid=30 pi3.l=0 FQCGPN=pi=0si1 preXCgpn=tn=0npi=0ti=1nd=b0042422044001pi=0si1 cgPart= cgPat=b0042422044001 cgpn=tn=0npi=0ti=1nd=8980pi=0si3 cgpnVM= unXCgpn=tn=0npi=0ti=1nd=b0042422044001pi=0si1 cName=locale: 1 Name: (Operator) Jared TAC UnicodeName: (Operator) Jared TAC pi: 0 DD=ti=1nd=4321pi=0si1 origDD=ti=1nd=4321pi=0si1 preXCdpn=tn=0npi=0ti=1nd=4321pi=0si0 preXTagsList=SUBSCRIBER preXPosMatchList=4321 cdPart=d15d1a00-02a2-34a7-e0d9-7d653b500c6d cdPat=4321 cdpn=tn=0npi=0ti=1nd=4321pi=0si1 cdpnVMbox= localPatternUsage=5 connectedPatternUsage=0 itrPart= itrPat= LRPart= LRPat= LR=tn=0npi=0ti=1pi=0si1 LRVM= LRName=locale: 1 Name: Call Manager UnicodeName: pi: 0 FQOCpdn=ti=1nd=4321pi=0si1 fFQLRNum=pi=0si1 oPart=d15d1a00-02a2-34a7-e0d9-7d653b500c6d oPat=4321 oCpdn=tn=0npi=0ti=1nd=4321pi=0si1 oCdpnVM= oRFR=354 oName=locale: 1 Name: UnicodeName: pi: 0 ts=SUBSCRIBER posMatches=4321 withTags= withValues= rdn.l=0IpAddrMode=0 ipAddrType=0 ipv4=10.15.3.60:0 region=LasVegas_Region capCount=1 ctiActive=F ctiFarEndDev=1 ctiCCMId=4 cgPtyDev=SEP002497A964CF callInst=0 confCallInst=0 OLF=1Supp DTMF=3DTMF Cfg=1DTMF Payload=0isOffNetDev=F bc.l=0 bc.itr=0 bc.itc=0 bc.trm=0 bc.tm=0 maxForwards=70 cgpnMaskedByRedirect=T callingDP= featCallType=0 callingUserId= UnicodeName: muteEnabled=0 associatedCallCI=0 featurePriority=1 nonTargetPolicy=0 unconsumedDigits= suppressMOH=T numPlanPkid =47120c78-3381-7a76-dc37-fc87210358cb networkDomain= bitMask=0 SetupReason=0 routeClass=1 sideACmDeviceType=1 protected=1 ControlProcessType=0 tokens=0 isPresent=F transitCount=0 geolocInfo=null locPkid= locName= deductBW=F fateShareId= videoTrafficClass=Unspecified oFromAnalogDvc=F bridgeParticipantID= callingUsr= remoteClusterID= isEMCCDevice=F lHPMemCEPN= cHPMemCEPN= isParamSet=FTransparentData=null CanSupportSIPTandN=false TransId=0 AllowBitMask=0x0 UserAgentOrServer= OrigDDName=locale: 1 Name: UnicodeName: pi: 0 mCallerId= mCallerName=LatentCaps=null icidVal= icidGenAddr= oioi= tioi= ptParams= receivedPAID= routeHdr= routeCepn= requestURI= PCVFlag=F originallyHadISUP=F isIMSFinalRoute=F IMSMode=0 SideABibEnabled= 0 isCgpnNonPreemptable=F isCdpnNonPreemptable=F origDP= lastRedirectingDP= originalLRG= lastRedirectingLRG= nwLoc=0 rstr= FarEndDeviceName= ReferredByUri= Session-ID: ;remote= hdrMOH=0 CAL={v=ffffffff, m=ffffffff, tDev=F, res=F, devType=0}

Esta es la invitación a MS para esta llamada con ID de llamada 50459200-8261109d-125c82-2080fe0a.

47540202.001 |10:40:29.610 |AppInfo |SIPTcp - wait_SdlSPISignal: Outgoing SIP TCP message to 10.55.100.23 on port 5060 index 95625 
[12124747,NET]
INVITE sip:4321@10.55.100.23:5060 SIP/2.0
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee04b9db528
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
To: <sip:4321@10.55.100.23>
Date: Fri, 11 Nov 2016 18:40:29 GMT
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
Supported: timer,resource-priority,replaces
Min-SE: 1800
User-Agent: Cisco-CUCM11.0
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 101 INVITE
Expires: 180
Allow-Events: presence, kpml
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Call-Info: <sip:10.1.1.60:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Session-ID: 00000000000000000000000000000000;remote=00000000000000000000000000000000
Cisco-Guid: 1346736640-0000065536-0000177089-0545324554
Session-Expires: 1800
P-Asserted-Identity: "(Operator) Jared TAC" <sip:555666@10.1.1.60>
Remote-Party-ID: "(Operator) Jared TAC" <sip:555666@10.1.1.60>;party=calling;screen=yes;privacy=off
Contact: <sip:555666@10.1.1.60:5060;transport=tcp>;isFocus
Max-Forwards: 70
Content-Length: 0

Ésta es la llamada que no pudo negociar un códec.
Pasemos al MS 200 OK con SDP y averigüemos por qué no se pudo establecer un códec.

47540802.002 |10:40:29.819 |AppInfo |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 10.55.100.23 on port 5060 index 95625 with 1024 bytes:
[12124760,NET]
SIP/2.0 200 Ok
Via: SIP/2.0/TCP 10.1.1.60:5060;branch=z9hG4bK201ee04b9db528
To: <sip:4321@10.55.100.23>;tag=ds23933dcf
From: "(Operator) Jared TAC" <sip:555666@10.1.1.60;x-nearend;x-refci=71233302;x-nearendclusterid=TACOp;x-nearenddevice=SEP002497A964CF;x-nearendaddr=555666;x-farendrefci=71234316;x-farendclusterid=TACOp;x-farenddevice=10.15.255.254;x-farendaddr=5255553333>;tag=3695142~47718da5-fef5-1f81-1709-6f389f40258a-71233612
Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60
CSeq: 101 INVITE
Content-Length: 309
Contact: <sip:4321@10.55.100.23:5060;transport=tcp>
Content-Type: application/sdp
Allow: INVITE, BYE, CANCEL, ACK, NOTIFY, INFO, UPDATE
Server: MediaSense/10.x
v=0
o=CiscoORA 2153 1 IN IP4 10.55.100.23
s=SIP Call
c=IN IP4 10.55.100.23
t=0 0
m=audio 34370 RTP/AVP 102 0 8 9 18
a=rtpmap:102 MP4A-LATM/90000
a=fmtp:102 profile-level-id=24;object=23;bitrate=64000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=recvonly

Solicitud de conexión de medios para los dos CI. ID de MediaManager: 847431. Siga este ID para ver por qué no ha podido configurar los medios.

47540844.001 |10:40:29.825 |AppInfo |ARBTRY-ConnectionManager-wait_MediaConnectRequest(71233611,71233612)
47540850.001 |10:40:29.826 |AppInfo |SIG-MediaManager-(847431)::wait_MediaConnectRequest, CI(71233611,71233612), capCount(1,8), mcNodeId(0,0), xferMode(8,16), reConnectType(0), mrid (0, 0) IFCreated(0 0) proIns(0 0), AC(0,0), party1DTMF(1 3 0 0 0) party2DTMF(1 0 0 1 1),reConnFlag=0, connType(2,3), IFHand(0,0),MTP(0,0),MRGL(3cf3871c-f9ac-1a4b-9261-105cb3c6cb79,17b41810-a72d-d2e0-be30-8dffe05ce048) videoCap(0 0), mmCallType(0),FS(0,0), IpAddrMode(0 0) aPid(4, 242, 2044), bPid(4, 83, 215774) EOType(0 0) () honorCodec(0 0)
47540874.000 |10:40:29.829 |SdlSig |CACInfoRes |waitCACInfoRes |MediaManager(4,100,142,847431) |ReservationMgr(4,100,111,1) |4,100,14,460202.37477^10.55.100.23^* |[R:N-H:0,N:3,L:0,V:0,Z:0,D:0] CI= 0 aCI=71233611 bCI=71233612 pol=0 rsvpStatus=1 aVideoTrafficClass=0 bVideoTrafficClass=0 sessJoined=F staIdx_no_agent=0 locationstatus=( AudioBWReserved) eoSent=F aAgent: confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 bAgent: confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 aPort: NumPort =0 bPort: NumPort =0 otherAgentPort: NumPort =0
47540874.001 |10:40:29.829 |AppInfo |DET-MediaManager-(847431) - waitCACInfoRes_CACInfoRes- qosType=0 videoEsc=0 mNoVideoResvAttempted=1 VideoCall=0

La relación de región indica que existe una velocidad máxima de bits de audio de 8 kbps entre estas regiones.

47540874.002 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::waitCACInfoRes_CACInfoRes, rsvp(0,0), E2E RegionBwKbps[ A=8 V = 384 I = 2000000000 ] ,deviceAcaps(0) deviceBCaps(0),noVideoResv(1), mmAllowedCallType(0x00000000)
47540874.003 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::mapCapabilitiesToMMCallType - Call is set to Audio Only - vidCall = 0)
47540874.004 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::buildMtpXcoderAllocList, savedConnectionCount=0, QosType=0
47540874.005 |10:40:29.829 |AppInfo |DET-RegionsServer::matchCapabilities-- savedOption=3, PREF_NONE, regionA=(null) regionB=(null) latentCaps(A=0, B=0) kbps=8, capACount=1, capBCount=8
47540874.006 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::checkAudioPassThru, param(bPostMTPAllocation=0,chkTrp=1), capCount(1,8), mtpPT=1, aPT=2

Pty1 proviene de LasVegas_Region y está configurado para (4,20)=G711 ulaw. (Este es el teléfono del agente).
Pty2 proviene de SignalHill_Region y tiene 8 capacidades. (Troncal SIP de MS).

47540874.007 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::preCheckCapabilities, region1=LasVegas_Region, region2=SignalHill_Region, Pty1 capCount=1 (Cap,ptime)= (4,20), Pty2 capCount=8 (Cap,ptime)= (44,0) (4,20) (2,20) (6,20) (11,20) (12,20) (15,20) (16,20)
47540874.008 |10:40:29.829 |AppInfo |DET-RegionsServer::matchCapabilities-- savedOption=0, PREF_NONE, regionA=(null) regionB=(null) latentCaps(A=0, B=0) kbps=8, capACount=1, capBCount=8
47540874.009 |10:40:29.829 |AppInfo |RegionsServer: applyCodecFilterIfNeeded - no codecs remained after filtering so restored original 0 caps

Hay una discordancia de capacidades ya que G711 ulaw utiliza una velocidad de bits de 64 kbps, por lo que CUCM intenta invocar un transcodificador. La corrección de las relaciones de región elimina el problema.

47540874.010 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::preCheckCapabilities, caps mismatch! Xcoder Reqd. kbps(8), filtered A[capCount=0 (Cap,ptime)=], B[capCount=4 (Cap,ptime)= (11,20) (12,20) (15,20) (16,20)] allowMTP=0 numXcoderRequired=1 xcodingSide=1
47540874.011 |10:40:29.829 |AppInfo |DET-MediaManager-(847431)::prepareInitialConnectionList, Party1CapCount=1 Party2CapCount=8 XcoderRequired=1 xcodingSide=1 allowMTP=0

Para resolver esto, debe corregir la relación de región en CUCM para permitir una velocidad de bits máxima mayor entre regiones: al menos 64 kbps. Se recomienda crear una nueva región para MS. Configure que sea exactamente igual que la región anterior, excepto que debe aumentar la velocidad máxima de bits a al menos 64 kbps, y asegúrese de que cualquier región que utilice el valor predeterminado del sistema para la velocidad máxima de bits debe aumentarse a al menos 64 kbps. Copie el conjunto de dispositivos establecido en el troncal MS SIP, asigne la nueva región a este conjunto de dispositivos, asigne el conjunto de dispositivos al troncal MS SIP y restablezca el troncal MS SIP. 

Códecs comunes

En CUCM, los códecs se enumeran con el formato (Cap,ptime), donde Cap = capability = codex y ptime = packetization time. Aquí hay una lista de códecs importantes que puede ver en el campo 'Cap':

G711 Alaw with 64 kbps bit rate = 2
G711 Ulaw with 64 kbps bit rate = 4
G722 with 64 kbps bit rate      = 6
G722 with 56 kbps bit rate      = 7
G722 with 48k kbps bit rate     = 8
G728                            = 10
G729                            = 11
G729 Annex A                    = 12
G729 Annex B                    = 15