The documentation set for this product strives to use bias-free language. For the purposes of this documentation set, bias-free is defined as language that does not imply discrimination based on age, disability, gender, racial identity, ethnic identity, sexual orientation, socioeconomic status, and intersectionality. Exceptions may be present in the documentation due to language that is hardcoded in the user interfaces of the product software, language used based on RFP documentation, or language that is used by a referenced third-party product. Learn more about how Cisco is using Inclusive Language.
This document describes common issues seen on MediaSense (MS) which cause lost recordings or unplayable on the server.
Cisco recommends you have the knowledge on these topics:
The information in this document is based on these software and hardware versions:
The information in this document was created from the devices in a specific production environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, ensure that you understand the potential impact of any command.
One of the most common issues encountered on MS is that it is not able to access recordings because the media is removed from MS. This document explains how to better troubleshoot these types of scenarios in order to help understand why the recorded media is not on MS.
You are unable to play recordings from MS Search and Play. The track size shows 00:00:00 and there is a yellow exclamation mark to the left of the recording that indicates that there is no media as shown in the image.
The pruning configuration on MS can prune recordings if they have passed a certain age or if more disk space is needed for newer recordings.
You can find your pruning settings at this location: Cisco MediaSense Administration > Administration > Prune Policy Configuration. If the Do not automatically remove associated data and converted media files setting is selected, then when recordings are pruned from the server, their meta data remains, and a yellow exclamation mark with an error "Record Cancelled" or "Zero Size Tracks" is displayed as shown in the image.
The fastest way to verify this is with groom.log generated by the Media service.
You can collect the groom.log and/or orapurge.log from the Media service log collection from Real Time Monitoring Tool (RTMT), or you can quickly use the Command Line Interface (CLI):
Note: The groom log shows the raw SMD file, which is associated with the session ID from the Media Service's MySQL database. It's cumbersome in order to get a session ID from an SMD file as it takes root access to the server. These logs are only good in order to understand of the age of the pruned recordings.
For example, these logs shows that recordings from January 4, 2017, get pruned:
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.logshow a little more detail as the session ID and track numbers are presented:
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
In this example, you see recordings have been pruned much faster than the 90 prune settings.
In the ORA-ora logs, you see that recording with Session ID 56e5159848cca971, came into MS just fine and closed with a CLOSED_NORMAL state.
The recording started at epoch time 1483987536761, which is 'Mon Jan 9 13:45:36 2017 GMT-5:00’.
You see that the media URL in here as well, which shows a recording saved.
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"}
You see that this recording gets purged in the orapurge.log. Track1 and Track0 are for the separate parties in the recording:
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.
The ORA-ora logs show us the sessions that are pruned, it includes the session previously shown:
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
This shows the 6 pruned sessions:
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
You can also see when recordings are pruned to reclaim disk space for new recordings. When a MS reaches the critical condition of the /recordedMedia partition reaching 90 percent, older recordings (even if younger than the age threshold) are pruned to make room for new ones. MS prunes the batches of 200 recordings until the disk space is at or lower than 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
Recording archival to an SFTP server was introduced in MS 10.5. In some cases, you can have media pruned before archival can take place. A common issue is that the connectivity to the SFTP server goes down, and while the recording has been archived a long time in advance, MS cannot do so due to connection issues with the SFTP server. MediaSense repeatedly tries to archive a recording if the attempt to archive fails.
Here is an example of what you would see in the /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
Archived Session ID: ebcf45708f010bc1
SFTP Server IP: 10.75.41.225
MS converts the recording to MP4 for archival:
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 processes a request to transfer the recording:
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 attempts to connect to the SFTP server, but it fails with a Java Secure Channel (JSch) exception. JSch is a Java implementation of SSHv2 that MS uses for its SSH client:
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
This example is with Built-in-Bridge (BiB) recording. In the CUCM/MS vocabulary, the near-end device is the device that transmits the audio to MS, this is a CUCM phone in the case of the phone configured with BiB recording. The far-end device is the device transmitting media to the recorded device. In the majority of cases, this is a CUCM SIP trunk, which is the device from which a PSTN phone's SIP signaling comes from. Equivalently, you can think of the near-end signaling is transmitted by the recorded device and the far-end signaling being received from the recorded device.
In this example, this is the call information you can see from 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
You see that there was likely a codec negotiation failure on the near-end call from the CUCM phone to the MS SIP trunk. xrefCIs seen are the CUCM CIs for the actual call and not for the call recorded by 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
On CUCM logs, these are the CIs found for the call to be recorded are:
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
Near-end Call:
First Invite MS receives: Call-ID: 50459200-8261109d-125c82-2080fe0a@10.1.1.60 from the near-end device.
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 sends 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 sends 200 OK with 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
You get an ACK from CUCM for this call without SDP, which means that a codec was not chosen by CUCM.
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 ends the call.
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
Far-end Call:
Second Invite MS receives: Call-ID: 50459200-8261109d-125c83-2080fe0a@10.1.1.60 from the far-end device.
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 sends 180 ringing for the second call.
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 sends 200 OK with 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 sends ACK with SDP. For this call leg, G729 is chosen since both servers support this from the 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 ends the call.
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 Records the call as a failure.
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]
JSON file is created and saved in 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
Here is the digit analysis for the CUCM phone's BiB that calls the MS dial pattern. b0042422044001 is the BiB DN.
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
CUCMs response to the digit analysis. Here is the CI for the call: 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,
CI from BiB to 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)
This CI is set up with CI 71233612. This is the CI for CUCM-MS SIP trunk connection. These two CIs form the SIP Call-ID.
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}
Here is the invite to MS for this call with Call-ID 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
This is the call that failed to negotiate a codec.
Let's jump to the MS 200 OK with SDP and figure out why a codec could not be set.
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
Media connect request for the two CIs. MediaManager ID: 847431. Follow this ID to see why you could not set up media.
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
The region relationship dictates that there is a max audio bit rate of 8kbps between these regions.
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 is coming from the LasVegas_Region and is set for (4,20)=G711 ulaw. (This is the agent phone).
Pty2 is coming from the SignalHill_Region and has 8 capabilities. (This is the MS SIP Trunk).
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
There is a capabilities mismatch since G711 ulaw uses a 64kbps bit rate, so CUCM tries to invoke a transcoder. Correcting the region relationships eliminates the issue.
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
To resolve this, you must correct the region relationship on CUCM to allow a larger maximum bit rate between regions - at least 64 kbps. It is recommended you create a new region for MS. Configure it to be the exact same as the old region except that you must increase the max bit rate to at least 64 kbps, and ensure any regions that use the system default for the max bit rate must be increased to at least 64 kbps. Copy the device pool set on the MS SIP trunk, assign the new region to this Device Pool, assign the Device Pool to the MS SIP trunk, reset the MS SIP trunk.
In CUCM, the codecs are listed in the form (Cap,ptime), where Cap = capability = codex and ptime = packetization time. Here is a list of important codecs you can see in the 'Cap' field:
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
Revision | Publish Date | Comments |
---|---|---|
1.0 |
26-Oct-2017 |
Initial Release |