Ressalva: Este documento foi redigido com base no CUCM 5+, mas é aplicável a todas as versões de CUCM com pequenas alterações.
Ressalva 2: Este é um primeiro esboço e estou receptivo a contribuições. Se você vê algo errado, ou que poderia estar melhor, comente no documento e lhe adicionarei como contribuidor.
Habilitar traces
Siga estedocumento para habilitar CUCM traces. Preste atenção às caixas de seleção H.225 e H.245.
Recrie o problema / Realize chamadas de teste
Obtenha o número do chamador, o número chamado, e a hora da chamada.
Download dos traces
Siga estas instruções para fazer o download dos traces do CallManager de todos os nós do cluster durante o período de tempo da chamada.
Download da aplicação analítica avançada
Eu prefiro Notepad++, mas todo editor de texto com marcação de texto ou busca de palavras servirá. Se você vai utilizar unix2dos, pode usar o bloco de notas padrão do Windows. Download de uma ferramenta como TripleComboToolou TranslatorX pode ser útil.
Analizar traces
Este é o momento que a diversão começa. Temos pastas cheias de arquivos de trace. Você pode baixar os traces que usei para este exemplo no arquivo anexado H323Trace.zip. Em algum lugar dentre os gigabytes de arquivos esta nossa chamada. Abaixo dicas de como encontrá-la e em seguida analisá-la.
Encontre a chamada
Eu gosto de usar uma ferramenta como WinGrep, ou mesmo Linux grep, para obter apenas uma ideia de quais arquivos de traces olhar.
A chamada de exemplo tem os seguintes detalhes:
Número do chamador - 7021004
Número chamado - 8011000
Hora da chamada (obtido do menu do telefone Placed Calls) - 11:45
As buscas seriam coisas como
cn="7021004
dd="8011000
Estes dois strings permitirão encontrar a linha Digit Analysis em CUCM. cn representa o número do chamador. dd representa o número chamado. Vamos dar uma olhada no grep para encontrar os arquivos de trace que nos servirão:
jasburns@jasburns-gentoo ~/trace/H323Trace $ grep -REi --include "ccm*.txt" "dd=\"8011000" * cucm7-sub1/2010-06-24_11-47 16/cm/trace/ccm/sdi/ccm00000002.txt:06/24/2010 11:45:32.095 CCM|Digit analysis: match(pi="2", fqcn="7021004", cn="7021004",plv="5", pss="", TodFilteredPss="", dd="8011000",dac="0")
O comando grep usou
- R recursivo
- E expressões regulares prolongadas (caso queiramos utilizar regex)
- i busca que não diferencia maiúsculas e minúsculas (caso fiquemos com preguiça)
-- inclua para procurar somente em arquivos que tenham nomes como ccm*.txt
Se conhecemos apenas o número do chamador, podemos mudar nosso string de busca de acordo. Se não recebemos nenhum resultado, podemos remover a porção cn ou dd e buscar apenas pelo número. Se procurar pelo número com 7 dígitos e continuar sem resultado, pode procurar pelos últimos 4 dígitos até encontrar a chamada.
Baseando-nos na busca, podemos concluir que a chamada esta no arquivo:
cucm7-sub1/2010-06-24_11-47-16/cm/trace/ccm/sdi/ccm00000002.txt Também vemos coisas interessantes na linha Digit Analysis:
pss="" e TodFilteredPss="" significam que o telefone do chamador tem um Calling Search Space configurado como <None>. Este valor é geralmente uma lista ordenada de Partitions dentro do CSS do chamador.
Vamos abrir o arquivo de trace ccm*02.txt em nosso editor de texto e verificar a linha acima.
Localize o chamador
Se voltamos a algumas linhas anteriores, podemos ver o telefone SCCP que fez a chamada
06/24/2010 11:45:32.089 CCM|StationInit: (0000003) SoftKeyEvent softKeyEvent=1(Redial)
A sessão TCP desse telefone IP em particular é 0000003. Isso indica que este telefone foi o terceiro a se registrar desde o início do processo CCM neste nó. Podemos fazer um grep para esta sessão TCP em particular para obter todas as mensagens SCCP enviadas para o telefone e desse telefone.
StationInit - O telefone enviou esta mensagem para o CUCM
StationD - O CUCM enviou esta mensagem para o telefone
Vamos usar Notepad++ para destacar isso no trace. Destaque a sessão TCP, clique com o botão direito, selecione "Using 1st Style". A partir de agora isso estará destacado em azul em qualquer lugar no arquivo de trace.
Encontre o ID do processo para esta chamada e o ID do processo para o número chamado
Cada leg da chamada tem um CallID. Este é um identificador exclusivo para esse leg da chamada. É geralmente referenciado como CI.
Cada chamada também tem um processo cdcc. Este é processo primário de controle de chamada.
Cada número chamado tem um processo associado com ele. Este é o lugar para onde CUCM vai enviar a chamada.
Podemos aprender tudo isso nas linhas logo após Digit Analysis
06/24/2010 11:45:32.095 CCM|Digit analysis: insert daResEntry to daResCache.
KeyCi=42514739 ,PID:Cdcc(2,174,4)
Aprendemos o CI para a chamada 42514739, assim como o cdcc(2,174,4). É útil destacá-los também no trace.
Através do dmpidreq e dos dmpidres (pedido e resposta) podemos obter o ID do processo para onde vamos rotear a chamada:
06/24/2010 11:45:32.096 CCM|Digit analysis: wait_DmPidRes- Partition=[] Pattern=[801XXXX]Where=[], cmDeviceType=[AccessDevice], OutsideDialtone =[1], DeviceOverride=[0],PID=RouteListControl(1,100,61,2)
Vemos que o Route Pattern utilizado foi 801XXXX, e que este pattern aponta para RouteListControl. O ID do processo deste é (1,100,61,2).
Busque o processo chamado no nó correto
O processo Route List Control existe no nó 1 (publisher) e estamos atualmente no subsciber. Isto existe dentro do processo CUCM (100). Isto significa que o subscriber terá que enviar uma mensagem para o Route List Control no publisher.
Normalmente associo Node IDs aos nomes do servidores através dos traces SDL. Por exemplo, podemos ver que cucm7-sub1 é nó 2 (SDL002_*.txt)
Como sabemos que o sinal foi enviado ao nó 1, e nó 2 é o subscriber, podemos procurar nas pastas dos traces SDL do nó 1. Nó 1 é sempre o publisher (mas seu publisher pode não ser nó 1, baseado na sua versão de CCM, e se ou não você tenha ativado ou desativado serviços).
Vamos abrir o trace CCM do publisher na hora em questão, 11:45:32.096
cucm7-pub\2010-06-24_11-47-15\cm\trace\ccm\sdi\ccm00000002.txt
06/24/2010 11:45:32.100 CCM|RouteListControl::idle_CcSetupReq- RouteList(ICT_RL)
Está aqui o pedido do subscriber para o publisher. Podemos ver que a chamada está indo para uma Route List nomeada “ICT_RL”.
A Route List analisa os Route Groups, e você pode ver que selecionamos um membro do RG
06/24/2010 11:45:32.101 CCM|SMDMSharedData::findLocalDevice - Name=ICTto801
Key=005cee5b-ef72-4919-4855-5983ba8b23f2 isActvie=1 Pid=(1,153,7) found
Por sorte o PID deste dispositivo dentro do Route Group está também no nó 1. Se descemos um pouco nos traces, vemos a chamada H.323 indo através do InterClusterTrunk.
Encontre o Outbound Setup H.225
Vemos o processo criado para esta sessão H.225. O CUCM está tentando estabelecer uma conexão TCP.
06/24/2010 11:45:32.188 CCM|H225D::restart0_TcpConnectionInfo: H225Cdpc(1,100,154,3)
Em seguida veremos o Setup H323:
06/24/2010 11:45:32.193 CCM|SPROCRas - {
h323-uu-pdu
{
h323-message-body setup :
{
protocolIdentifier { 0 0 8 2250 0 5 },
sourceAddress
{
dialedDigits : "7021004",
h323-ID : {"7021004", {0, 0, 0, 0}, ...}
},
sourceInfo
{
vendor
{
vendor
{
t35CountryCode 181,
t35Extension 0,
manufacturerCode 18
},
productId '436973636F43616C6C4D616E61676572'H,
versionId '31'H
},
terminal
{
},
mc FALSE,
undefinedNode FALSE
},
destinationAddress
{
dialedDigits : "8011000"
},
activeMC FALSE,
conferenceID '807B41849C7D31C2030003010E302CCF'H,
conferenceGoal create : NULL,
callType pointToPoint : NULL,
sourceCallSignalAddress ipAddress :
{
ip '0E302C15'H,
port 1720
},
|<CLID::StandAloneCluster><NID::CUCM7-PUB><LVL::State Transition><MASK::0100>
06/24/2010 11:45:32.193 CCM|callIdentifier
{
guid
'807B41849C7D31C2030003010E302CCF'H
A parte mais importante desta mensagem para buscar o restante da chamada é o guid '807B41849C7D31C2030003010E302CCF'H. Este é um identificador único da chamada. Podemos usar grep ou wingrep para buscar por esse guid. Podemos descobrir quantos arquivos de trace possui este guid e em seguida abrí-los no editor de texto.
Junto com o corpo da mensagem H.225, há também uma parte compacta da mensagem H.225:
11:45:32.193 CCM|Out Message -- H225SetupMsg -- Protocol= H225Protocol
11:45:32.193 CCM|Ie - H225BearerCapabilityIe IEData= 04 03 80 90 A2
11:45:32.193 CCM|Ie - H225CallingPartyIe IEData= 6C 09 00 81 37 30 32 31 30 30 34
11:45:32.193 CCM|Ie - Q931CalledPartyIe IEData= 70 08 80 38 30 31 31 30 30 30
11:45:32.194 CCM|IsdnMsgData2= 08 02 00 03 05 04 03 80 90 A2 6C 09 00 81 37 30 32
11:45:32.212 CCM|In Message -- H225CallProceedingMsg -- Protocol= H225Protocol
11:45:32.212 CCM|IsdnMsgData1= 08 02 80 03 02 7E 00 55 05 21 80 06 00 08 91 4A 00
Isto nos permite uma busca sucinta de todas as mensagens de uma chamada. Podemos ver que a primeira mensagem é um Setup e contem os valores ASCII dos números chamado e chamador.
Chamador 37 30 32 31 30 30 34
Chamado 38 30 31 31 30 30 30
Como estão em ASCII e são dígitos, tudo que precisa fazer para obter os números chamador e chamado é remover os 3 de cada dupla de números. Isto é muito útil para confirmar qual número foi enviado ao dispositivo H323 na outra ponta.
A segunda mensagem é uma mensagem denominada Proceeding.
Associamos estas mensagens através do identificador ISDN, que começa no terceiro octeto.
A porção do identificador é 0 03. O primeiro carácter indica a direção. 0 representam a direção de saída neste caso. A direção de entrada será Saída + 8 (hex), ou 8 neste caso.
Encontre a porta H.245 que foi negociada
Mensagens como Setup, Proceeding, Alerting, Connect, e Release Complete serão trocadas através do protocolo H.225. Estas mensagens são para controle de chamada. Há um protocolo completamente diferente chamado H.245 que é usado para negociar os endereços IP, portas UDP, e codec que serão usados para os fluxos de média da chamada.
Na mensagem Alerting ou Connect, o dispositivo chamado adicionará um endereço IP e porta na seção nomeada h.245Address. Esta porta faz com que o dispositivo chamador inicie uma nova sessão TCP para o dispositivo chamado com objetivo de trocar mensagens H.245.
Usei Notepad++ para procurar pelo guid em todos os arquivos de trace; em seguida verifiquei cada mensagem H.225 até encontrar uma com a porta:
Você pode ver que a porta H.245 é 58820e vem na mensagem Connect às 11:45:34 (quando o número chamado atendeu a chamada). Destaquei esta porta porque é crucial para a nossa próxima etapa.
Encontre o H.245 TTPid baseado na porta H.245
Agora que temos a porta H.245, podemos procurar pelo identificador do processo que permitirá que encontremos todas as mensagens H.245 para esta chamada.
Nota |
Este procedimento abaixo aplica somente para chamadas “Slow Start”. Documentarei “Fast Start” em outro momento. |
Se a porta H.245 vem em uma mensagem H.225 de entrada, procure nos traces por essa porta. Em seguida, será realizado o processamento para criação do processo H.245.
Se a porta H.245 é enviada em uma mensagem H.225 de saída, procure nos traces por essa porta. Já foi feito o processamento para criar o processo H.245 e então foi enviada a mensagem com o número de porta.
Esta é uma mensagem H.225 de entrada do nosso exemplo, então procuraremos pela porta H.245 até que veremos uma linha como esta:
06/24/2010 11:45:34.167 CCM|H245Interface(3)::start_Transition, (H245Client session)
ip = (14.48.44.80), port = 58820, TA provided by Callee
Neste exemplo vemos que a interface H.245 criada tem um ID igual a 3 H245Interface(3). Todas mensagens H.245 para esta chamada serão trocadas neste processo. Procure até que veja uma mensagem como a seguinte para obter o processo ID completo:
06/24/2010 11:45:34.181 CCM|H245ASN - TtPid=(1,100,16,3) -Outgoing -value
MultimediaSystemControlMessage ::= request : terminalCapabilitySet
Este é um TCS de saída. O identificador que usaremos como nosso string de busca futura é TtPid=(1,100,16,3). Destaque com uma outra cor.
Use Notepad++ "Find in all Open Documents" (ou uma busca similar em seu editor de texto) para obter a sessão H.245 completa desde o início da chamada até o final:
Encontre as capacidades no Terminal Capability Set
Cada lado anunciará as capacidades suportadas na mensagem Terminal Capability Set (TCS). Um lado anunciará inicialmente todas as capacidades suportadas. O outro lado responderá com as capacidades suportadas e que foram anunciadas pelo lado inicial.
TCS de saída anuncia suporte a:
{
capabilityTableEntryNumber3,
capability receiveAudioCapability : g711Ulaw64k: 40
},
{
capabilityTableEntryNumber4,
capability receiveAudioCapability : g711Alaw64k: 40
},
{
capabilityTableEntryNumber5,
capability receiveAudioCapability : g729wAnnexB: 6
},
{
capabilityTableEntryNumber6,
capability receiveAudioCapability : g729AnnexAwAnnexB: 6
},
{
capabilityTableEntryNumber7,
capability receiveAudioCapability : g729 : 6
},
{
capabilityTableEntryNumber8,
capability receiveAudioCapability : g729AnnexA: 6
},
{
capabilityTableEntryNumber9,
capability receiveAndTransmitUserInputCapability : dtmf: NULL
G.711U/A @ até 40 milissegundos de empacotamento (4 amostras de dados por quadro, com cada amostra levando 10msec)
G.729/A/B @ 6 amostras de dados por quadro (60 milissegundos de empacotamento, como cada amostra leva 10msec)
Nota: |
G.711 usa o intervalo de empacotamento entre pacotes RTP no TCS O G.729 usa o número de amostra de dados de 10msec por pacote RTP dentro do TCS Se você compreende que cada amostra tem 10msec de comprimento então a conversão entre os dois é consideravelmente simples. O empacotamento mais comum é de 20msec, ou 2 amostras de voz por pacote RTP. |
Se verificamos as capacidades de entrada, vemos que todas as mesmas capacidades são suportadas.
Encontre o codec, os endereços IP, e as portas UDP usadas
Quando voltamos aos traces do Subscriber, onde o telefone chamador está registrado, podemos ver que as configurações de região estão igual a G.711 (64kbps, como impresso nos traces)
06/24/2010 11:45:34.194 CCM|RegionsServer::MatchCapabilities -- kbps=64,
capACount=6, capBCount=8
No publisher, dizemos ao dispositivo H.323 que estamos usando o G.711 @ 20 milissegundos
06/24/2010 11:45:34.246 CCM|H245ASN - TtPid=(1,100,16,3) -Outgoing -value
MultimediaSystemControlMessage ::= request : openLogicalChannel :
{
forwardLogicalChannelNumber1,
forwardLogicalChannelParameters
{
dataType audioData : g711Ulaw64k : 20,
Da mesma forma recebemos uma mensagem para G.711 @ 20msec
No subscriber, podemos continuar buscando pela sessão TCP e ver que o telefone chamador SCCP foi notificado para abrir um canal de áudio G.711. O telefone responde (StationInit) dizendo que escutará na porta UDP 24418.
06/24/2010 11:45:34.255 CCM|StationInit: (0000003) OpenReceiveChannelAck Status=0,
IpAddr=IpAddr.type:0ipAddr:0x0e302ccf000000000000000000000000(14.48.44.207),
Port=24418, PartyID=33554435
Se voltamos ao nó onde a sessão H.245 está em curso, vemos a mensagem OpenLogicalChannelAck. Observe que o número de porta UDP RTP que nós enviamos no leg H.323 é a mesma porta que o telefone respondeu no SCCP ORCAck, 24418.
06/24/2010 11:45:34.257 CCM|H245ASN - TtPid=(1,100,16,3) -Outgoing -value
MultimediaSystemControlMessage ::= response : openLogicalChannelAck :
{
forwardLogicalChannelNumber 1,
forwardMultiplexAckParameters h2250LogicalChannelAckParameters :
{
sessionID 1,
mediaChannel unicastAddress : iPAddress :
{
network '0E302CCF'H,
tsapIdentifier 24418
},
O novo OpenLogicalChannelAck de entrada diz que o número chamado estará escutando em 23362
06/24/2010 11:45:34.259 CCM|H245ASN - TtPid=(1,100,16,3) -Incoming -value
MultimediaSystemControlMessage ::= response : openLogicalChannelAck :
{
forwardLogicalChannelNumber 1,
forwardMultiplexAckParameters h2250LogicalChannelAckParameters :
{
sessionID 1,
mediaChannel unicastAddress : iPAddress :
{
network '0E302CCC'H,
tsapIdentifier 23362
},
Voltando ao publisher onde o telefone chamador SCCP esta registrado, vemos CUCM o instruindo a enviar RTP a este novo IP e porta, usando o codec previamente estabelecido.
06/24/2010 11:45:34.260 CCM|StationD: (0000003) startMediaTransmission
conferenceID=42514739 passThruPartyID=33554435 remoteIpAddress=IpAddr.type:0
ipAddr:0x0e302ccc000000000000000000000000(14.48.44.204) remotePortNumber=23362
milliSecondPacketSize=20 compressType=4(Media_Payload_G711Ulaw64k)
Indo adiante na chamada, o número chamado pressiona Hold, Resume e End Call. Você pode usar todas as técnicas previamente discutidas para analisar o comportamento destas etapas em detalhes.
