Twilioブログ

ゼロからはじめるぜ! Twilio - コラム: コールログの時間を正しく読む

masamitsu.saito


masa_salute1.jpgこんにちは、ネットワークエンジニアのまさです。ゼロからはじめるぜ!シリーズ、大分ご無沙汰しております。

シーズン化してしまうと、連載するようなネタではないと書けずなかなか筆が進まない。なので、単発読み切りモノでもアリって勝手に決めました。

単発読み切りのネタの場合、題名を「ゼロからはじめるぜ! Twilio - コラム: 」とすることにします。Twilioを使い始めて間もない方、ちょっとした便利な使い方を教えてくれたらいいのにと密かに思っている方、こんなことをサポートの人に質問するのも気が引ける...と遠慮しているであろう方、大体このようなみなさんが読んだら「へぇ!」だの「ふーん」だの頷いてくれそうなネタを、このコラムでポツポツ書いていこうかなと思います。

さて、今回のネタですが「コンソール(管理画面)のログを表示した時のタイムスタンプ、あれって厳密にはどの瞬間の時刻なの?」です。

実は、ここ最近であるお客様から実際にあったご質問です。もう目から鱗。私も4年ほどこのサービスに携わってますが、なんとなくこのタイミングの時間だろうなと考えたことはあるものの、厳密に意識したことが無かった。このお問い合わせをきっかけに綺麗さっぱりと判明したので、お客様にご快諾いただき、みなさんにも情報共有したいと思った次第です。FAQに載せるつもりだったけど、どうせなら文量を増やして詳しく書こうと。「ゼロからシリーズ:コラム」の誕生です。

サンプルのコールフロー

せっかくなので実践に即してみます。以下のようなコール、よくやると思います。いわゆる、Twilioを介した転送電話です。ここから先に出てくる画像は、クリックしたらポップアップで大きいのが表示されます。ぜひ、別ウィンドーのポップアップを見ながら読み進んでください。

callflow.jpg左右に電話マークがあります。このサンプルでは両方とも「一般的な電話」を使っていますが、これがClientアプリであろうが、SIPフォンであろうが理屈は同じです。

左の電話がTwilio番号である 050-B に電話をかけると、このTwilio番号の設定画面にある「A Call comes in」欄に設定されているWebhook URLを使い、WebサーバーからTwiMLを取ってきます。このTwiMLには DIAL動詞 が1つだけ存在し、callerIdを050-B にして090-C に電話を発信するフローを実現しています。

このフローにおいて、Twilioを挟んだ左側のコール、つまり、Twilioに対するインバウンドのコールを「親コール」と呼びます。そして、Twilioを挟んだ右側のコール、つまり、Twilioからアウトバウンドするコールを「子コール」と呼びます。実際このコールを体験している側にすれば、+81A と +8190C が電話でつながっているので1本のコールだと思っていることでしょう。しかし、実際にはTwilioを挟んで2つのコール(親コールと子コール)が存在し、それらの音声をTwilioシステムが橋渡しているのです。そして、親コールが読み込んだTwiMLが「+8190C」に新しい電話をかける、という子コールを生成しています。このように、2つのコールは親子関係がありますので、+8190C と話している間に、親コール側を切ってしまうと当然に子コールも切れてしまいます。

さて、実際にこのフローで電話して通話が終了しました。さっそくコンソールでログを見てみましょう... と言いたいところですが、ログを見る前に、まずこのフロー、厳密には一体裏側でどんなことしてるか気になりませんか? 気になるでしょう、気にしてください、気になることうけあい。先にその話をします。

このフローは実際どんなことをしてるか?

この親子のコール、フロー図にしてみるとこんな感じです。

transactionflow_new.jpg図中の丸付き赤数字は、この次のセクションで説明するコールログ画面のタイムスタンプに対応しています。上から順に説明します。

+81A がTwilio番号 +8150B に電話をかけます。相手側電話キャリアからTwilioに対して「電話をかけるぜ」という信号を出し、Twilioはこれに対し「OK」で応答します。この瞬間の時刻が で、親コールのログ画面の中で「開始時間」に表示されます。

Twilioは「着信したらURLを叩く」という基本動作をしますので、この +8150Bに設定してある Webhook URLからTwiMLを取ってきます。このHTTPを出した瞬間の時刻がで、ログ画面では「リクエスト調査」のPOSTにかかれているURLにの横のタイムスタンプで表示されます。この親コールが、このTwiMLで生成される全ての処理の「親」になります。

このHTTPリクエストの応答が相手側サーバー(URL先)から全て戻ってくるまでの「秒数」が に記されています。単位は ミリ秒(1/1000秒)です。この所要時間は、みなさんのWebサーバーの処理スピードや、インターネット回線の状況等の影響を受けることになります。TwilioがみなさんのWebサーバーからTwiMLを受け取るとTwilioは直ちにTwiMLの処理を行います。

このフローではTwiMLにDIAL動詞があるので、Twilioは子コールを生成して、電話の発信をします。Twilioが+8190C 側のキャリアへ「電話をかけるぜ」という信号を出し、相手側キャリアから「わかった、ちとまってろ、呼び出すわ」という信号が届きます。そして、最終的に「出たぞ」を意味する「OK」がTwilioに届いた瞬間の時刻が に記されています。これはすなわち、「子コールの開始時刻」です。つまり、の時刻にの秒数を足した時刻を、の時刻から引いた結果出てきた秒数は「TwilioがTwiMLを解析して実行するのに掛かった所要時間+子コールのDIALが成立するまでに掛かった所要時間の合計」を意味します。カンが鋭い方は「ん?」と思ったかもしれません。先にこちらから申し上げちゃいますが「Twilioが子コールを発信し始めた時間」は分からないのです。仕様だと思ってください。

ここからは、左の電話と右の電話の楽しいおしゃべりタイムです。

はぁいっっ!!! 宴もたけなわですがおしゃべりもう止めて。右から電話を切ります。すると、相手側キャリアからTwilioへ「切るからね」という信号が届きます。Twilioはこれに対して「OK」を返します。このOKを返した瞬間の時刻が に記されており、これはすなわち、「子コールの終了時刻」です。Twilio側から切った場合も同じです。矢印が出て行く順番が違うだけで、結局、どっちだろうがこのコールの「切るからね」に対して「OK」の時間をタイムスタンプに表示しています。

お気づきだろうか?

通話は平和に終わったのにまだ までしか解説してない。図は まで採番している...

の下にある青丸は何でしょうか? これは のHTTPアクセスで取ってきたTwiMLの続きを処理する部分です。さっき実行したDIALは、このTwiMLに書かれた先頭の動詞の処理にすぎません。子コールが終わった瞬間、このDIAL動詞の処理が終わりますので、Twilioは次の動詞の処理に移ります。もし、このDIAL動詞の次にSAY動詞でも書かれていれば、親コール側の +81A の人は、このSAY動詞が喋っているのを聞くことになります。この青丸は、DIAL動詞以降に書かれている残りのTwiMLを処理している部分です。このサンプルでは、DIAL動詞1個だけのTwiMLを使ったので、TwiMLも最後まで処理したことになり、これで終了になります。

親コールが取ってきたTwiMLの全てを処理し終えて、初めてTwilioは親コールを終了するための「切るからね」信号を親コールの相手へ送信します。それまでの間はずっと親コールはつながったままです。この概念はTwilioを使う上で非常に大事ですので覚えておいてください。親コールが取ってきた全てのTwiMLの内容を処理し終わるまで親コールは継続します。このサンプルにおいては、+81A が電話をかけはじめてから子コールでの通話が終わるまでの全体が親コールの継続時間です。そして相手側キャリアから「OK」が返ってきた瞬間の時刻を として記し、これはすなわち、「親コールの終了時刻」です。

長くなりましたが、実際のコンソール画面のどこに該当するか確認してみましょう。

コンソールに表示されるログ

コンソールにログインし、さっきのフローに対するログを見るとこんな感じになっています。
ログ.jpg

まず最初に +81A からかかってくるので下の行が Incoming で親コール、この Webhook URLで読み込んだTwiML がDIAL動詞で +8190C にかけたものが上の行、 Outgoind Dial で子コールになります。それぞれのタイムスタンプをクリックすると、各コールの詳細画面が出てきます。

▼親コール
親コール.jpg

▼子コール
子コール.jpg

  • このエントリーをはてなブックマークに追加

Facebook コメント