Asteriskを利用するアプリケーションのデバッグ

Posted by rhoboro on 2021-02-21

前回の記事では、AsteriskをDockerで起動してレジを取れましたが、まだhello worldが聞こえない状態です。　

そのデバッグで行ったことをメモしておきます。

$ git clone https://github.com/rhoboro/asterisk-docker.git
$ git checkout 0.1

# リポジトリ内にあるconfをそのまま使う場合
$ docker run --rm -it -p 5060:5060 -p 5060:5060/udp -p 10000-10010:10000-10010/udp myasterisk:0.1

Asteriskのログの確認方法

Asterisk CLIを起動するとAsteriskをCLIから操作でき、起動時のオプションでログを表示させることもできます。

今回はAsteriskをフォアグラウンドで起動しているので、docker runコマンドを実行するだけでCLIも起動します。 もしデーモンとしてAsteriskが起動している場合は、次のようにCLIを起動できます。

# -rでCLIを起動
# -vはVerboseのことで、数を増やすほど表示されるログが増える
$ asterisk -vvvvvr

この状態でレジを取ると次のようなログが表示されます。

*CLI>
    -- Added contact 'sip:[email protected]:33666;transport=UDP;rinstance=311ae5d6b66985d5' to AOR '6001' with expiration of 60 seconds
  == Endpoint 6001 is now Reachable
    -- Removed contact 'sip:[email protected]:33666;transport=UDP;rinstance=311ae5d6b66985d5' from AOR '6001' due to request
  == Contact 6001/sip:[email protected]:33666;transport=UDP;rinstance=311ae5d6b66985d5 has been deleted
  == Endpoint 6001 is now Unreachable
    -- Added contact 'sip:[email protected]:59207;transport=UDP;rinstance=b27b9bd35b42a92b' to AOR '6001' with expiration of 60 seconds
  == Endpoint 6001 is now Reachable

また、次のコマンドでRTPに関するログ（=リアルタイム通信のログ）も表示されるようにします。

*CLI> rtp set debug on
RTP Debugging Enabled

それでは、この状態で100をダイアルしてみます。 次のようなログが表示され、AsteriskからRTP packetが送信されていることがわかります。 これがhello-worldの音声データです。

9cc03ea54b08*CLI>
  == Setting global variable 'SIPDOMAIN' to 'host.docker.internal'
    -- Executing [100@from-internal:1] Answer("PJSIP/6001-00000000", "") in new stack
       > 0x7f81b800ac50 -- Strict RTP learning after remote address set to: 127.0.0.1:8000
    -- Executing [100@from-internal:2] Wait("PJSIP/6001-00000000", "1") in new stack
    -- Executing [100@from-internal:3] Playback("PJSIP/6001-00000000", "hello-world") in new stack
Sent RTP packet to      127.0.0.1:8000 (type 00, seq 032624, ts 000160, len 000160)
    -- <PJSIP/6001-00000000> Playing 'hello-world.slin' (language 'en')
Sent RTP packet to      127.0.0.1:8000 (type 00, seq 032625, ts 000320, len 000160)
...
Sent RTP packet to      127.0.0.1:8000 (type 00, seq 032694, ts 011212, len 000012)
    -- Executing [100@from-internal:4] Hangup("PJSIP/6001-00000000", "") in new stack
  == Spawn extension (from-internal, 100, 4) exited non-zero on 'PJSIP/6001-00000000'

RTP packetのログをよく見ると送信先が127.0.0.1:8000になっています。 いまはホストからレジを取っているため、コンテナ内で127.0.0.1:8000に送ってもホストにはデータが届かないはずです。

SIPの通信内容を見る

Asteriskがデータを127.0.0.1:8000に送っていることから、Asteriskとクライアントの通信中にどこかでこの値が指定されていると考えられます。 Asteriskとクライアントの通信にはSIPと呼ばれるプロトコルが使われており、SIPはHTTPと似たテキストベースで人間が目で見てもわかりやすいです。 ということで、SIPの通信内容をみてみましょう。

今回のdocker runコマンドでは5060ポートをポートフォワーディングしてDockerに送信していますが、この5060ポートはSIPがデフォルトで使うポートになっています。 そのため、このポートをtcpdumpでパケットキャプチャしていきます。

下記コマンドを実行し、100をダイアルしてみました。

$ sudo tcpdump -i lo0 port 5060 -A
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo0, link-type NULL (BSD loopback), capture size 262144 bytes
出力の全文はこちら 
13:26:51.986016 IP localhost.33666 > localhost.sip: SIP: INVITE sip:100@localhost;transport=UDP SIP/2.0
E..|[email protected].|INVITE sip:100@localhost;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:33666;branch=z9hG4bK-524287-1---12e99d9c5e6c5444;rport
Max-Forwards: 70
Contact: <sip:[email protected]:59207;transport=UDP>
To: <sip:100@localhost>
From: <sip:6001@localhost;transport=UDP>;tag=979b6e42
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
User-Agent: Z 5.4.12 v2.10.13.2
Allow-Events: presence, kpml, talk
Content-Length: 326

v=0
o=Z 1613881611883 1 IN IP4 127.0.0.1
s=Z
c=IN IP4 127.0.0.1
t=0 0
m=audio 8000 RTP/AVP 106 9 98 101 0 8 3
a=rtpmap:106 opus/48000/2
a=fmtp:106 sprop-maxcapturerate=16000; minptime=20; useinbandfec=1
a=rtpmap:98 telephone-event/48000
a=fmtp:98 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv

13:26:51.991308 IP localhost.sip > localhost.33666: SIP: SIP/2.0 401 Unauthorized
[email protected]/2.0 401 Unauthorized
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---12e99d9c5e6c5444
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=z9hG4bK-524287-1---12e99d9c5e6c5444
CSeq: 1 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1613881611/ff867498198770effa7784bfcb2390d9",opaque="18f47b372e2e78c2",algorithm=md5,qop="auth"
Server: Asterisk PBX 16.8.0
Content-Length:  0


13:26:51.991720 IP localhost.33666 > localhost.sip: SIP: ACK sip:100@localhost;transport=UDP SIP/2.0
E..k} [email protected] sip:100@localhost;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:33666;branch=z9hG4bK-524287-1---12e99d9c5e6c5444;rport
Max-Forwards: 70
To: <sip:100@localhost>;tag=z9hG4bK-524287-1---12e99d9c5e6c5444
From: <sip:6001@localhost;transport=UDP>;tag=979b6e42
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
CSeq: 1 ACK
Content-Length: 0


13:26:52.014086 IP localhost.33666 > localhost.sip: SIP: INVITE sip:100@localhost;transport=UDP SIP/2.0
[email protected] sip:100@localhost;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:33666;branch=z9hG4bK-524287-1---6cf540e02e732f2a;rport
Max-Forwards: 70
Contact: <sip:[email protected]:59207;transport=UDP>
To: <sip:100@localhost>
From: <sip:6001@localhost;transport=UDP>;tag=979b6e42
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
User-Agent: Z 5.4.12 v2.10.13.2
Authorization: Digest username="6001",realm="asterisk",nonce="1613881611/ff867498198770effa7784bfcb2390d9",uri="sip:100@localhost;transport=UDP",response="be0ed3350bad6a190b8dbdb2b146a44f",cnonce="a14e9f20bfcffeac32d931bf5e605ad1",nc=00000001,qop=auth,algorithm=md5,opaque="18f47b372e2e78c2"
Allow-Events: presence, kpml, talk
Content-Length: 326

v=0
o=Z 1613881611883 1 IN IP4 127.0.0.1
s=Z
c=IN IP4 127.0.0.1
t=0 0
m=audio 8000 RTP/AVP 106 9 98 101 0 8 3
a=rtpmap:106 opus/48000/2
a=fmtp:106 sprop-maxcapturerate=16000; minptime=20; useinbandfec=1
a=rtpmap:98 telephone-event/48000
a=fmtp:98 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv

13:26:52.020609 IP localhost.sip > localhost.33666: SIP: SIP/2.0 100 Trying
[email protected]/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Content-Length:  0


13:26:52.026470 IP localhost.sip > localhost.33666: SIP: SIP/2.0 200 OK
E..+....@..................+SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=2955ed65-3167-4a75-9424-6adee7b58f03
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Contact: <sip:172.17.0.2:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   224

v=0
o=- 3268875883 3 IN IP4 172.17.0.2
s=Asterisk
c=IN IP4 172.17.0.2
t=0 0
m=audio 10004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

13:26:52.528383 IP localhost.sip > localhost.33666: SIP: SIP/2.0 200 OK
E..+)H..@..................+SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=2955ed65-3167-4a75-9424-6adee7b58f03
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Contact: <sip:172.17.0.2:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   224

v=0
o=- 3268875883 3 IN IP4 172.17.0.2
s=Asterisk
c=IN IP4 172.17.0.2
t=0 0
m=audio 10004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

13:26:53.528578 IP localhost.sip > localhost.33666: SIP: SIP/2.0 200 OK
E..+.j..@..................+SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=2955ed65-3167-4a75-9424-6adee7b58f03
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Contact: <sip:172.17.0.2:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   224

v=0
o=- 3268875883 3 IN IP4 172.17.0.2
s=Asterisk
c=IN IP4 172.17.0.2
t=0 0
m=audio 10004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

13:26:55.524657 IP localhost.sip > localhost.33666: SIP: SIP/2.0 200 OK
E..+....@..................+SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=2955ed65-3167-4a75-9424-6adee7b58f03
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Contact: <sip:172.17.0.2:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   224

v=0
o=- 3268875883 3 IN IP4 172.17.0.2
s=Asterisk
c=IN IP4 172.17.0.2
t=0 0
m=audio 10004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

13:26:59.522334 IP localhost.sip > localhost.33666: SIP: SIP/2.0 200 OK
E..+....@..................+SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:33666;rport=59207;received=172.17.0.1;branch=z9hG4bK-524287-1---6cf540e02e732f2a
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
From: <sip:6001@localhost>;tag=979b6e42
To: <sip:100@localhost>;tag=2955ed65-3167-4a75-9424-6adee7b58f03
CSeq: 2 INVITE
Server: Asterisk PBX 16.8.0
Contact: <sip:172.17.0.2:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   224

v=0
o=- 3268875883 3 IN IP4 172.17.0.2
s=Asterisk
c=IN IP4 172.17.0.2
t=0 0
m=audio 10004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

SIPはHTTPと同じくヘッダーがあり、その後空行を挟みボディがある構造となっています。 中ほどにある次のログを見ると、クライアントからのINVITEリクエストのボディに127.0.0.1や8000を見つけることができました。

13:26:52.014086 IP localhost.33666 > localhost.sip: SIP: INVITE sip:100@localhost;transport=UDP SIP/2.0
E....!..@...................INVITE sip:100@localhost;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:33666;branch=z9hG4bK-524287-1---6cf540e02e732f2a;rport
Max-Forwards: 70
Contact: <sip:6001@172.17.0.1:59207;transport=UDP>
To: <sip:100@localhost>
From: <sip:6001@localhost;transport=UDP>;tag=979b6e42
Call-ID: s66Gyc4zYrHb1QTOp-u7YA..
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
User-Agent: Z 5.4.12 v2.10.13.2
Authorization: Digest username="6001",realm="asterisk",nonce="1613881611/ff867498198770effa7784bfcb2390d9",uri="sip:100@localhost;transport=UDP",response="be0ed3350bad6a190b8dbdb2b146a44f",cnonce="a14e9f20bfcffeac32d931bf5e605ad1",nc=00000001,qop=auth,algorithm=md5,opaque="18f47b372e2e78c2"
Allow-Events: presence, kpml, talk
Content-Length: 326

v=0
o=Z 1613881611883 1 IN IP4 127.0.0.1
s=Z
c=IN IP4 127.0.0.1
t=0 0
m=audio 8000 RTP/AVP 106 9 98 101 0 8 3
a=rtpmap:106 opus/48000/2
a=fmtp:106 sprop-maxcapturerate=16000; minptime=20; useinbandfec=1
a=rtpmap:98 telephone-event/48000
a=fmtp:98 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv

このボディの情報はSDPと呼ばれ、リアルタイム通信で利用するIPアドレスや圧縮形式といったセッション情報を記述したものになっています。 つまり、これらのセッション情報を交換することで、SIPのエンドポイント(UserAgent)間どうしの通信が可能になり、このSDP情報の交換こそがSIPの目的となります。

--- 2021/02/21 追記[ここから] ---

SIPのログに関しては、下記のほうがtcpdumpを使うよりもわかりやすく表示してくれることに気づきました。

*CLI> pjsip set logger on

--- 2021/02/21 追記[ここまで] ---

ここまでの情報まとめ

ここまでで分かったことをまとめておきます。

  • Asteriskは音声データを送信している
  • ただし、送信先が127.0.0.1:8000になっている
  • 127.0.0.1:8000を指定しているのはクライアント
  • Dockerコンテナ内の127.0.0.1:8000はクライアント（ホスト）の127.0.0.1:8000ではない

ここからクライアントがデータを受信できる正しいIPアドレスとポートを指定できると音声が聞こえてきそうです。 なお、解決策のひとつとしてAsteriskとクライアントを同じネットワーク内に配置する方法が思いつくのですが、わたしはDocker Desktop for Macを利用しているため別の方法を探す必要がありそうです。

--- 2021/02/21 追記[ここから] ---

その後、Twitterでのつぶやきのように色々考えていましたところ、コンテナとホストは同じLAN内にいる別端末だと考えると、ホストのIPアドレスが指定できれば良いことに気づきました。 つまりクライアントでのSIPサーバーの指定時に、、LAN内のDNSサーバー（わたしの環境ではWi-Fiルーター）を１度介して通信するようlocalhostではなくホストのIPアドレスを指定します。 これにより、クライアントソフト（わたしの環境ではZoiper）が待ち受けるIPアドレスとポートが意図通りにSDPに載り、無事100へのダイアルで「hello world」が流れてくるようになりました。

--- 2021/02/21 追記[ここまで] ---

tags: Docker, Asterisk