はじめに
本ドキュメントは、Cisco Unified Border Element (CUBE) において IOS-XE 17.4.1, 17.3.2 で実装された VoIP Trace ログの取得方法を紹介します。VoIP Trace ログは、コールに関連する SIP のシグナリングメッセージや呼制御の状態などの情報をメモリ上に保存します。デフォルトで有効化されているため、何か問題が発生した場合に、過去のコールの履歴を debug コマンドなしで追跡することができます。
VoIP Trace ログの取得
以下のコマンドで VoIP Trace ログを取得できます。show voip trace all コマンドで全てのログが取得できますが、量が多いため、show voip trace cover-buffers コマンドで該当のコールの correlator などを確認し、show voip trace correlator <correlator> コマンドで該当のコールを出力することができます。
correlator は incoming コールと outgoing コールを紐づける ID のため、correlator を指定すると関連するコールを一度に確認できます。
Router#show voip trace ?
all Display all VoIP Traces ... 全てのログを出力
call-id Filter traces based on Internal Call Id ... 内部コールID を指定してログを出力
correlator Filter traces based on FPI Correlator ... Correlator を指定してログを出力
cover-buffers Display the summary of all cover buffers ... Trace のコールの一覧を出力
session-id Filter traces based on SIP Session ID ... SIP Session ID を指定してログを出力
sip-call-id Filter traces based on SIP Call Id ... SIP Call ID を指定してログを出力
statistics Display statistics for VoIP Trace ... VoIP Trace の統計情報を出力
show voip trace cover-buffers コマンドでコールの一覧を取得します。Search-Key は 発信元番号:宛先番号:CallID が記載されるため、show voip trace cover-buffers | section 2027:3000 などのコマンドでコールを検索することも可能です。目的のコールが確認できたら correlator ID などをメモしておきます。
Router#show voip trace cover-buffers
------------------ Cover Buffer ---------------
Search-key = 2027:883000:64
Timestamp = *Apr 29 15:26:35.042
Buffer-Id = 1
CallID = 64
Peer-CallID = 65
Correlator = 1
Called-Number = 883000
Calling-Number = 2027
SIP CallID = 47328d00-1ec1c702-4798-82e6470a@192.168.0.130
SIP Session ID = 82c975c9004050008000aaaabbbbcccc
GUID = 47328D000000
-----------------------------------------------
------------------ Cover Buffer ---------------
Search-key = 2027:3000:65
Timestamp = *Apr 29 15:26:35.046
Buffer-Id = 2
CallID = 65
Peer-CallID = 64
Correlator = 1
Called-Number = 3000
Calling-Number = 2027
SIP CallID = 1E07F33A-A83611EB-80468CAC-CF92ED3B@192.168.0.133
SIP Session ID = 82c975c9004050008000501cb0077777
GUID = 47328D000000
-----------------------------------------------
...
correlator ID などを指定して Trace ログを表示します。SIP メッセージ、ダイヤルピア、切断理由や RTP ポートなどが確認できます。
Router#show voip trace correlator 1
------------------ Cover Buffer ---------------
Search-key = 2027:883000:64
Timestamp = *Apr 29 15:26:35.042
Buffer-Id = 1
CallID = 64
Peer-CallID = 65
Correlator = 1
Called-Number = 883000
Calling-Number = 2027
SIP CallID = 47328d00-1ec1c702-4798-82e6470a@192.168.0.130
SIP Session ID = 82c975c9004050008000aaaabbbbcccc
GUID = 47328D000000
-----------------------------------------------
0: *Apr 29 15:26:35.042: //64/47328D000000/CUBE_VT/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:883000@192.168.0.133:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.0.130:5060;branch=z9hG4bK47a32afffdef
From: <sip:2027@192.168.0.130>;tag=18368~3fe57a0b-d81f-4f34-9b98-275aa2fda235-17825884
To: <sip:883000@192.168.0.133>
Date: Thu, 29 Apr 2021 15:26:35 GMT
Call-ID: 47328d00-1ec1c702-4798-82e6470a@192.168.0.130
Supported: 100rel,timer,resource-priority,replaces
Min-SE: 1800
User-Agent: Cisco-CUCM12.5
...
4: *Apr 29 15:26:35.042: //64/47328D000000/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_NONE, Next State = STATE_IDLE, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE
5: *Apr 29 15:26:35.042: //64/47328D000000/CUBE_VT/SIP/MISC/Matched Dialpeer: Dir:Inbound, Peer-Tag: 100
6: *Apr 29 15:26:35.043: //64/47328D000000/CUBE_VT/SIP/FSM/Offer-Answer: Event = E_SIP_INVITE_SDP_RCVD, Current State = S_SIP_EARLY_DIALOG_IDLE, Next State = S_SIP_EARLY_DIALOG_OFFER_RCVD
7: *Apr 29 15:26:35.043: //64/47328D000000/CUBE_VT/SIP/FSM/IWF: Event = E_SIP_IWF_EV_RCVD_SDP, Current State = S_SIP_IWF_SDP_IDLE, Next State = S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT
8: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/MISC/Media Stream Parameters: Stream Type = voice+dtmf, Stream State = STREAM_ADDING Negotiated Codec = g711ulaw, Negotiated DTMF Type = rtp-nte, Stream Index = 1
9: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/API: cc_api_update_interface_cac_resource (0)
10: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/API: voip_rtp_allocate_port (8000)
11: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/MISC/Media Stream Parameters: Stream Type = voice+dtmf, Stream State = STREAM_ADDING Negotiated Codec = g711ulaw, Negotiated DTMF Type = rtp-nte, Stream Index = 1
12: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/API: cc_api_call_setup_ind_with_callID (0)
13: *Apr 29 15:26:35.044: //64/47328D000000/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_IDLE, Next State = STATE_RECD_INVITE, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE
14: *Apr 29 15:26:35.045: //64/47328D000000/CUBE_VT/SIP/Msg/ccsipDisplayMsg:
...
116: *Apr 29 15:26:40.298: //64/47328D000000/CUBE_VT/SIP/Msg/ccsipDisplayMsg:
Received:
BYE sip:883000@192.168.0.133:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.0.130:5060;branch=z9hG4bK47a633fa885e
From: <sip:2027@192.168.0.130>;tag=18368~3fe57a0b-d81f-4f34-9b98-275aa2fda235-17825884
To: <sip:883000@192.168.0.133>;tag=1FE152-1822
Date: Thu, 29 Apr 2021 15:26:35 GMT
Call-ID: 47328d00-1ec1c702-4798-82e6470a@192.168.0.130
User-Agent: Cisco-CUCM12.5
Max-Forwards: 70
P-Asserted-Identity: <sip:2027@192.168.0.130>
CSeq: 103 BYE
Reason: Q.850;cause=16
Session-ID: 82c975c9004050008000501cb0077777;remote=82c975c9004050008000aaaabbbbcccc
Content-Length: 0
118: *Apr 29 15:26:40.298: //64/47328D000000/CUBE_VT/SIP/FSM/Event-Action: Event = SIPSPI_EV_NEW_MESSAGE, Current State = STATE_ACTIVE
119: *Apr 29 15:26:40.298: //64/47328D000000/CUBE_VT/SIP/MISC/Call Disconnect: Initiated at: 0x1702028, Originated at:0x1702021, Cause Code = 16
120: *Apr 29 15:26:40.298: //64/47328D000000/CUBE_VT/SIP/API: cc_api_call_disconnected (0)
121: *Apr 29 15:26:40.298: //64/47328D000000/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_ACTIVE, Next State = STATE_DISCONNECTING, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE
122: *Apr 29 15:26:40.299: //64/47328D000000/CUBE_VT/SIP/API: voip_rtp_destroy_dp_session (0)
123: *Apr 29 15:26:40.299: //64/47328D000000/CUBE_VT/SIP/FSM/Media-State: Event = E_IPIP_MEDIA_SERV_EV_XCODER_RESET_STREAM, Current State = CNFSM_CONTAINER_STATE, Next State = S_IPIP_MEDIA_SERV_STATE_IDLE
124: *Apr 29 15:26:40.299: //64/47328D000000/CUBE_VT/SIP/API: voip_rtp_update_callinfo (0)
125: *Apr 29 15:26:40.299: //64/47328D000000/CUBE_VT/SIP/API: cc_api_bridge_drop_done (0)
129: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/MISC/Call Disconnect: Initiated at: 0x260070A, Originated at:0x260070B, Cause Code = 16
131: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/API: cc_api_update_interface_cac_resource (0)
132: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/FSM/Event-Action: Event = SIPSPI_EV_CC_CALL_DISCONNECT, Current State = STATE_DISCONNECTING
133: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/API: voip_rtp_delete_dp_session (0)
134: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/API: cc_api_call_disconnect_done (0)
135: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/FSM/SPI-State-Change: Current State = STATE_DISCONNECTING, Next State = STATE_DEAD, Current Sub-State = STATE_NONE, Next Sub-State = STATE_NONE
136: *Apr 29 15:26:40.300: //64/47328D000000/CUBE_VT/SIP/MISC/Error: sipSPIFlushDeferredQueue: Invalid deferredQueue
...
TranslatorX ツールによる VoIP Trace ログの解析
debug ccsip message のログと同様に VoIP Trace ログも
TranslatorX ツールで解析することができます。
VoIP Trace ログの設定
VoIP Trace はデフォルトで有効化されています。
voice service voip
trace
VoIP Trace に利用されるメモリは、1000 MB もしくは IOS のメモリの 10% まで利用されます。プラットフォームによって異なります。
Router(config)#voice service voip
Router(conf-voi-serv)#trace
Router(conf-serv-trace)#?
Voip Trace submode commands:
default Set a command to its defaults
exit Exit from voice service voip trace mode
memory-limit Set limit based on memory used
no Negate a command or set its defaults
shutdown Shut Voip Trace debugging
Router(conf-serv-trace)#memory-limit ?
<10-1000> Specify maximum memory limit in MB
platform Use 10 percent of available memory
統計情報
show voip trace statistics コマンドで、VoIP Trace ログの利用状況が確認できます。
Router#show voip trace statistics
VoIP Trace Statistics
Tracing status : ENABLED at *Apr 29 14:52:44.857
Memory limit configured : 231735296 bytes
Memory consumed : 136816 bytes (0%)
Total call legs dumped : 0
Oldest trace dumped : NA
Latest trace dumped : NA
Total call legs captured : 6
Total call legs available : 6
Oldest trace available : *Apr 29 15:26:35.042, Search-key: 2027:883000:64
Latest trace available : *Apr 29 15:26:52.932, Search-key: 2027:3000:70
Total traces missed : 0
補足
- 問題の解析には VoIP Trace ログに加えて必要に応じて debug ログが必要になる場合があります
- REGISTER、SUBSCRIBE、NOTIFY、OPTIONS、INFO などのコールに直接関係しない SIP メッセージは出力されません
- 通信中のコールは表示されません。切断後、32 秒が経過してから VoIP Trace に出力されます
- terminal length 0 を実行した後に show voiip trace all を実行すると、出力量が多いためにルータに負荷がかかる可能性があります。
参考情報
