フレクトのクラウドblog re:newal

http://blog.flect.co.jp/cloud/からさらに引っ越しています

フレクトが行くAWS re:Invent 2018 Day. 1 〜黄金の風〜

こんにちは。 Cariot事業部の遠藤です。

ブログでは2回目の登場になります。ちなみに前回の記事はこちら(↓)

Jenkins × AWS CodeBuild × GitHubで複数コンテナを利用したビルドを試してみた - フレクトのクラウドblog re:newal

さて!
絶賛賑わいを見せている、ラスベガスで開催中のre:Invent 2018ですが、フレクトからは今年は4名、参加しています。

初日が終わったので、感想を書いていきますね(現地時間23:00)。

続きを読む

Ubuntu 18コンテナイメージにmanページがインストールされなくて困ったという話

エンジニアの佐藤です。こんにちは。今回は自分の作業上のメモみたいな話です。

筆者は日常の開発作業をクラウドインスタンスで行うことがあります。開発環境はDockerコンテナで実装した仮想デスクトップサーバーです。

blog.flect.co.jp

この開発環境、少し前にUbuntu 18.04のコンテナイメージから作り直したのですが、、、なんとmanページが一切使えません。

$ man git
No manual entry for git

調べていくと、なんとmanページのインストールが、以下の設定によって全部スキップされていました。

$ cat /etc/dpkg/dpkg.cfg.d/excludes
# Drop all man pages
path-exclude=/usr/share/man/*

このpath-exclude指定している行をコメントアウトし、git, git-manを再インストールすると、問題は解決しました。

Ubuntu 18のコンテナは初期イメージサイズを大幅に削減したと言われていましたが、こういう過激な方法が取られていたとは知りませんでした。まぁ、Dockerは通常サーバーとして使われ、筆者のようにクライアントとして使っている人はあまりいないということなのでしょう。

アウトバウンドリクエストはAWS NAT Gatewayに握りつぶされていた

エンジニアの佐藤です。こんにちは。今回はネットワークインフラのお話を書かせていただきたいと思います。

始まりは不具合連絡から

猛暑が続くある日のこと、お客さまから、とある開発システムの、とある機能が「動かないんだけど」という連絡を受けました。

筆者はすぐに問題現象を確認しましたが、確実に再現し、弁解の余地はありません。お詫びして、原因調査に取りかかりました。

この機能の実装はこうです。Salesforce(Visualforceページ)からApex処理を経て外部システムAにRESTリクエストを送信する。外部システムAはさらに外部システムSにRESTリクエストを送信する。レスポンスは順次回収され、適宜加工され、結果がSalesforce画面に表示される、というものです。 図に描くとこんな感じです。

f:id:masashi-sato-flect:20180824130318p:plain

報告された問題現象とは、ブラウザが10秒ほど応答停止したのちに、エラーが画面に表示されるというものです。エラーの内容から、筆者は、Salesforceがまともなレスポンスを受け取っていないんだろうと推測しました。そして10秒ブロックですから、一連のリクエスト連鎖のどこかでタイムアウトしたんだろうと思いました。筆者は外部システムAのログを観察しました。すると。。。外部システムSをリクエストする直前のログを最後に足取りが途絶えていました。

きっとSalesforceからシステムAへのリクエストが10秒でタイムアウトし、Visualforceページのエラーへとつながっていったのでしょう。
図に描くとこんな感じです。

f:id:masashi-sato-flect:20180824130349p:plain

システムSは「シロ」

次に筆者が疑ったのは、システムSです。実はシステムSは今回の機能開発に合わせて平行開発されたもので、開発中は多少問題があったこともあったのです。筆者はシステムAの内部から、Pythonの即席コードでシステムSにリクエストしてみました。すると。。。何の問題もなくレスポンスがあります。

f:id:masashi-sato-flect:20180824130406p:plain

原因は「聞か猿」ではなく「言わ猿」

「他人を最初に疑うのは良くないよな」と反省した筆者は、問題現象発生時のパケットキャプチャを採取することにしました。すると。。。システムSへのリクエストはそもそも送信されていないことがわかりました。そんなバカなと思って2度3度やってみましたが、結果は変わりません。技術者たる者、事実の前には謙虚でなくてはなりません。 リクエストがタイムアウトしたのではなく、そもそもリクエストしていなかったのです。

ここで筆者は困ってしまいました。というのも、このシステムA、他にも似たような処理を常時続けており、そちらには何の問題もないからです。DockerコンテナのJava実装された単一のプロセスで、あっちはよくてこっちはダメという状態なのです。システムAからリクエスト可能であることは、図3で確認されていますから、原因はシステムA側にあるはずです。

f:id:masashi-sato-flect:20180824130430p:plain

リブートで回復するが、再び発生

筆者はこの段階で、Dockerコンテナの再起動を考えました。どう考えてもおかしいので、コンテナプロセス内部に何か一時的な問題が起こっているのだろうと考えたのです。幸いロードバランサ化のコンテナクラスタで、ドレーンしてから再起動することで無停止再起動が可能でしたので、許可を得て実行しました。すると。。。ログにソケット強制クローズの警告が数十個出力されました。スローされた例外は org.apache.http.impl.execchain.RequestAbortedException 、「リクエストしたが、返事が来る前に、棄てられた。」

そんなばかな。システムSへのリクエストは、システムAにログインしてPython即席コードを実行すれば、通るのですよ。受信待機になるはずがないのです。DockerコンテナでBridgeネットワークを経由している点がPython即席コードと違うといえば違いますが、リクエスト先がシステムS以外の場合は成功しており、Dockerが原因とは考えにくい。

その一方で、コンテナ再起動により当初の機能は回復しました。レスポンス待ちのソケットを強制クローズすれば、システムAからシステムSの、新しいリクエストは通るのです。謎は以下2つに絞り込まれました。

  • なぜ受信待機のソケットが多数発生したのか。
  • 受信待機のソケットが多数発生すると、なぜシステムSへのリクエスだけ が送信されなくなるのか。

そのうち調査するか。。。と思っていた筆者でしたが、翌日再びお客さまから「やっぱり、動かないんだけど」の連絡が。。。
そんなばかな。。。こうなるともう逃げ道はない。筆者は覚悟を決めて徹底追及することにしました。

NATに目をつけ、受信待機ソケットの再現に成功

筆者は再び機能不全に陥ったシステムAを調査し、Dockerコンテナプロセスに多数の受信待ちソケットがあることを確認しました。

なぜこのようなソケットが発生するのか?筆者が次に疑ったのは、NATでした。実はこのシステムA、AWS VPCのプライベートネットワークセグメントに立てられたECSクラスタ上のサービスとして実装されており、アウトバウンドリクエストはVPCのNATゲートウェイを経由することにしていたのです。NATゲートウェイの詳細な仕様は以下の公式ページに書かれています。

Comparison of NAT Instances and NAT Gateways
https://docs.aws.amazon.com/AmazonVPC/latest/UserGuide/vpc-nat-comparison.html

詳しく読んでいくと、タイムアウトに関する以下のような記述がありました。

Timeout behavior
NAT Gateway: When a connection times out, a NAT gateway returns an RST packet to any resources behind the NAT gateway that attempt to continue the connection (it does not send a FIN packet).
NAT Instance: When a connection times out, a NAT instance sends a FIN packet to resources behind the NAT instance to close the connection.

NATについては、以前AWSはNAT用に特別調整したAMI(NAT Instance AMI)を提供して適宜使ってくれという姿勢でしたが、ある時からこれがサービス化され、NATゲートウェイと名付けられました。そして、その際になぜか、仕様が変わったようです。今回使っているのはNATゲートウェイですから、仮にもしシステムSへのリクエストがタイムアウトすると、システムA側には、何も通知されない。システムAから何か催促すればRSTパケットを返すとありますが、 HTTPリクエストが終わっていて、TCPキープアライブも設定されていなければ(今回は設定されていない)、そのような催促はない。永久待機です。

f:id:masashi-sato-flect:20180824130454p:plain

疑い深い筆者は、Python即席コードで悪いHTTPサーバーを書いて、受信待機ソケットの再現を試みました。

PORT = 8000

def Handler(request, client_address, server):
    n = int(sys.argv[1])
    print('wait {} secs'.format(str(n)))
    time.sleep(n)
    print('no response return')

with socketserver.TCPServer(("", PORT), Handler) as httpd:
    print("serving at port", PORT)
    httpd.serve_forever()

このサーバー、リクエストされたら指定秒数間スリープしたのち、何も言わずにソケットをクローズするという迷惑なものです。

クライアントは同じくPythonで以下のように実装しました。これ以上ない簡単な実装です。

address = sys.argv[1]
print('requesting ' + address)
res = requests.get(address)
print(res)

手元で実験すると、以下のようになりました。

$ python3 innocent_client.py http://localhost:8000
requesting http://localhost:8000
(中略)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response',))

なお、requests、特別に指定しないとタイムアウトはなし、つまり返信があるまで無制限待機となります。
http://docs.python-requests.org/en/master/user/advanced/#timeouts

これをNATゲートウェイ越しで動作させると。。。できました!サーバー側で360秒後にソケットをクローズしたにも関わらず、クライアント側では受信待機のソケットが、「来ぬ人を」待ち続けています。

f:id:masashi-sato-flect:20180824130510p:plain

タイムアウトを設定し、問題現象は解決へ

ここまで来ると受信待機ソケットの滞留を防止する方法は、タイムアウト設定ということになります。筆者は以下のようにタイムアウトを設定しました。

CloseableHttpClient httpClient = HttpClients.custom()
        (中略)
        .build();

HttpComponentsClientHttpRequestFactory requestFactory = new HttpComponentsClientHttpRequestFactory();

requestFactory.setHttpClient(httpClient);
requestFactory.setConnectTimeout(connectionTimeout); // タイムアウト追加
requestFactory.setReadTimeout(readTimeout); // タイムアウト追加

RestTemplate restTemplate = new RestTemplate((ClientHttpRequestFactory)requestFactory);

しかしこのタイムアウト、デフォルトでは無制限なのでしょうか?

調査すると、なんと「デフォルトでは無制限」のようでした。。。
https://hc.apache.org/httpcomponents-client-4.2.x/tutorial/html/connmgmt.html
CoreConnectionPNames.SO_TIMEOUT='http.socket.timeout': (中略) If this parameter is not set, connect operations will not time out (infinite timeout).

このコードをコミットすると、見事に問題現象が起こらなくなりました。どうやら問題現象の原因要因に正しくアプローチできたようです。

受信待機のソケットが多数発生すると、なぜシステムSへのリクエスだけ が送信されなくなるのか。

問題現象が解決してしまったのでこの点は謎なままなのですが、筆者は「リクエストスレッドプールが違っていたから」だと考えています。図4に戻りますが、システムDはAWS SDKを使用して呼び出しており、システムSはApache HTTP Componentsで呼び出していました。2つのリクエストスレッドプールが独立して確保されていたので、システムS側のプールスレッドが全部受信待機になったとしても、システムD側のプールスレッドには影響しなかったのでしょう。

そもそものきっかけは何なのか

最後の謎として、「システムSが通常応答するなら、なぜタイムアウトになったのか」という点があります。これについては、いまだに特定されていません。ひょっとすると普段は順調なのに夜間はダメとかなのかもしれません。

最後に

今回の問題を反省に、リクエストには必ずタイムアウトを設定する習慣をつけたいものです。今回調べたPythonのRequestsライブラリもJavaApache HTTP Componentsも、既定のタイムアウトは「なし」なのです。なんらかの理由でパケットが棄てられたら、「来ぬ人を」永久待機ということに容易になってしまいます。

最後までお読みくださり、ありがとうございました。

クラウドインスタンスでAndroid仮想デバイスを「ハードウェア仮想化付きで」動かす

みなさんこんにちは。エンジニアの佐藤です。今回はAndroid開発について書かせていただきたいと思います。と言っても、Androidアプリではなく、開発環境であるAndroid Studioについてです。

これまでの話

筆者は業務をしばしばVDI(仮想デスクトップ)環境で行なっています。
理由はネットワークの速度とリソースの柔軟性です。
VDIをホストするクラウドインスタンスは、ネットワークが速く、安定しています。オフィスの回線とは比較になりません。多量のデータを出し入れする仕事では、効率が上がります。また、CPU、メモリ、ストレージもその時の仕事に合わせて確保し、終わったら解放できますので、経済的です。

しかし、スマホ開発は別でした。これらの開発ではエミュレータを実行する必要があり、エミュレータは通常、ハードウェア仮想化機能を利用します。(仮想化オフでも動きますが、とてつもなく遅い。) 一方、クラウドインスタンスはそれ自体ハードウェア仮想化の中で動作しているため、ここでさらにハードウェア仮想化を利用するアプリを動かすことは、できなかったのです。

いえ、あるにはあったのですが、以下のような特別な仕掛けが必要でした。
Nested virtualization: How to run nested KVM on AWS or Google Cloud https://blogs.oracle.com/ravello/run-nested-kvm-on-aws-google

仕方がないので筆者は苦肉の策で、クラウドインスタンスAndroid Studioと、ローカル環境のエミュレータをつないだりしていました。

Android仮想デバイスとDocker開発環境をつなぐ http://blog.flect.co.jp/cloud/2017/04/androiddocker-c3b5.html

昨年ついにインスタンスで仮想化機能が提供に

しかし昨年、ついにクラウドインスタンスでもハードウェア仮想化が利用可能になりました。ありがたいことに、追加コストはかかりません。

AWSについては情報がありませんが、AzureとGCPでサポートが表明されました。

Introducing nested virtualization for Google Compute Engine. Thursday, September 28, 2017
https://cloudplatform.googleblog.com/2017/09/introducing-nested-virtualization-for.html

Nested Virtualization in Azure. Posted on July 13, 2017
https://azure.microsoft.com/en-us/blog/nested-virtualization-in-azure/

今回はこの機能を使って、GCPインスタンスで実行される仮想デスクトップ上でAndroid仮想デバイス(AVD)を「ハードウェア仮想化を使って」実行してみたいと思います。結論から言うと、この試みは目論見通りに成功しました。

手順

GCPインスタンスでハードウェア仮想化を有効にする手順は、以下の公式ドキュメントに書かれています。

Enabling Nested Virtualization for VM Instances https://cloud.google.com/compute/docs/instances/enable-nested-virtualization-vm-instances

手順はまず、ハードウェア仮想化を有効にした起動イメージを作成することから始まり、コマンドラインで実行する必要があります。この有効化、ライセンス付与という形態を取っていますが課金はありません。

gcloud compute images create nested-vm-imad
  --source-disk masashi-tw02  --source-disk-zone asia-east1-b \
  --licenses "https://www.googleapis.com/compute/v1/projects/vm-options/global/licenses/enable-vmx"

次にこの起動イメージでインスタンスをスタートします。このときプロセッサアーキテクチャにHaswellまたはSkylakeを指定します。

gcloud compute instances create example-nested-vm --zone asia-east1-b \
  --image nested-vm-image

このインスタンスSSHでログインして以下のコマンドを打って、「1」が返ることを確認します。

grep -cw vmx /proc/cpuinfo
1

これでハードウェア仮想化が有効になったはずです。Android Studioを実行してみましょう。

筆者は前出の「Docker開発環境」を使いました。ハードウェア仮想化とはつまりCPUの特別命令セットの使用のことですので、コンテナを特権モード(privileged=true)で動作させれば動作するのではないかと目論んでのことです。Android Studioを直接インストールするのではなく、インストール済みのコンテナをスタートさせました。

ハードウェア仮想化が、動いた!

Android Studioを起動したらAVD一覧を開き、AVDを追加します。この時 Select system image の所で「x86 images」の中から選択します。

f:id:masashi-sato-flect:20180714230243p:plain

こうして作成したAVDを起動すると。。。ありゃ、エラーです。

/dev/kvm のアクセス権が無いと言われてしまったので、このデバイスのオーナーをAVDの実行ユーザーに変えました。

sudo chown user1.user1 /dev/kvm

再度AVDを起動すると。。。動きました!この速度、確かにハードウェア仮想化の速さです。

f:id:masashi-sato-flect:20180714230430p:plain

試しにHello Worldを動かしてみると、ローカル環境同様に開発アプリがAVDにロードされました。

f:id:masashi-sato-flect:20180714230321p:plain

使えるの?

ようやく念願の「クラウド仮想デスクトップ+AVD」が実現したのですが、その性能はいかほどのものでしょうか。正直に言いますと、 「耐えられないほどではないが、かなり遅い」というのが筆者の正直な印象です。

ハードウェア仮想化を有効にしてもなお遅い理由として、仮想デスクトップなのでグラフィックのハードウェア支援が一切無いことが原因として考えられます。特にスマホアプリはアニメーションを多用し、通常は中間フレームはハードウェア支援で描画しますので、これを全部CPUでこなして、かつ、ネットワークで転送しなければならないというハンディが動作を遅くしていることは容易に想像できます。

ですが、全てのアプリケーションが常時激しいアニメーションを行うわけではないと思いますので、これは使い方次第なのではないでしょうか。

もう一つの問題として、AVDが多量のリソースを消費することがあります。図はAVDの実行中にtopコマンドでメモリ消費を調べたものですが、3GBを超えるメモリが使われています。

f:id:masashi-sato-flect:20180714230349p:plain

今時のスマホの性能を考えると仕方がないのかもしれませんが、しかし、この点についてはクラウドですし、メモリもCPUも時間買いできますので、必要なだけ確保すれば良いと思います。

ローカル環境と比べてメリットもあります。Android StudioもAVDも、初回インストール時のダウンロード容量がとにかく多く、オフィスや家庭の回線では非常に辛いものがあります。この点クラウドインスタンスのネットワークは高速でかつ安定しているので、なんでもサクサクダウンロードできてしまいます。 スタートアップまでの時間は、まちがいなくクラウドの方が速いでしょう。インストール済みコンテナやイメージを素早く展開できるという利点もあります。

今回の知見は、機会があればぜひ活用したいと思います。最後までお読みいただきありがとうございました。

あなたの身近にもあるかもしれない『ダブりデータ』

みなさんこんにちは。エンジニアの佐藤です。今回はIoTの話題をご紹介させていただきたいと思います。

重複データの蠢き

先日、とあるIoTシステムのログデータをETL(Extract, transform, load)処理によりDWHに収めました。このシステムは運用暦約1年で、利用量は右肩上がりで上昇してきました。蓄積データの活用が企画され、数億件のデータがDWHに集積されました。多数のデバイスが毎日送信して積み上げてきたものです。

ですが、およそコンピュータと名の付く物、何事も疑いの目で見なければなりません。筆者がまず気になったのは、「まともなデータなのか」という点です。数億レコードともなると、もはや個別確認はできません。どんなゴミが混入しているのかわかったものではありません。

「まともなデータ」の基準はいろいろあると思いますが、筆者が一番重要だと思うのは、一意性です。RDBMSで言えば「テーブルのキー項目は何か」ということになります。DWHにユニーク制約はありませんから、スキーマが一意性を担保することはありません。まずこの点から確認する必要があります。

このシステムの場合、送信データにはデバイスのID、対象事象発生時のデバイス時刻、シーケンス番号が含まれています。シーケンス番号は電源OFFでリセットされますから、一意ではありませんが、デバイスのIDは重複がないことが保証されています。時刻は外部の信頼できる時計に自動補正ですから、一旦正確だと前提しましょう。詳細は省きますが、 バイスID、事象発生時のデバイス時刻、ログ到着時刻の全てが重複することは、仕様上無いはずです。 DWHにはBigQueryを使っていますので、以下のようにクエリしてこの点を確認してみました。

#standardSQL
SELECT 
  xxxxx AS dt_log,
  xxxxx AS device_id,
  xxxxx AS device_time,
  COUNT(*) count
FROM table02 
WHERE _PARTITIONTIME = TIMESTAMP('2018-06-10')
GROUP BY dt_log, device_id, device_time
HAVING count > 1
※ 一部は伏字または仮の値にしています。

+-------------------------+-----------+---------------------+-------+
|         dt_log          | device_id |     device_time     | count |
+-------------------------+-----------+---------------------+-------+
| 2018-06-10 00:00:00.045 | 4641      | 2018-06-09 23:59:56 |     2 |
| 2018-06-10 00:00:00.572 | 9458      | 2018-06-09 23:59:57 |     2 |
| 2018-06-10 00:00:00.014 | 9499      | 2018-06-09 23:59:57 |     2 |
| 2018-06-10 00:00:00.235 | 1686      | 2018-06-09 23:59:58 |     2 |
| 2018-06-10 00:00:00.195 | 1712      | 2018-06-09 23:59:58 |     2 |
+-------------------------+-----------+---------------------+-------+

それ見たことか。ダブりデータです。 日付が変わった直後から約1秒間の間で発生しているように見えます。念には念を入れて受信した生データも比較してみましたが、完全に重複しています。 これはいわばデータの「バグ」。原因を特定せねばなりません。

何と何がダブっているのか

同じデータが2回DWHに登録された理由は何か?この原因追求のために役立つのが、私が「経路情報」と呼んでいる、レコードの出自に関する記録です。ETL処理の節目ごとにこの経路情報を追記していき、全てのレコードについて元ネタが特定できるように仕掛けておくのです。

今回のダブりデータについて経路情報(log_file_pos)を表示すると、以下のようになりました。簡単に解説しますと、「2018-06-09/1/343159(00717206)/00」は、2018年06月09日のログファイルに記録された、受信ホスト1番が出力したログファイルの第343159番目のデータで、ファイルの第717206行目に記録されている、という意味です。(末尾の「/00」は説明を省略します。)

+-------------------------+-----------+---------------------+----------------------------------+
|         dt_log          | device_id |     device_time     |           log_file_pos           |
+-------------------------+-----------+---------------------+----------------------------------+
| 2018-06-10 00:00:00.235 | 1686      | 2018-06-09 23:59:58 | 2018-06-09/1/343159(00717206)/00 |
| 2018-06-10 00:00:00.235 | 1686      | 2018-06-09 23:59:58 | 2018-06-10/1/003(00000006)/00    |
| 2018-06-10 00:00:00.195 | 1712      | 2018-06-09 23:59:58 | 2018-06-09/1/343158(00717205)/00 |
| 2018-06-10 00:00:00.195 | 1712      | 2018-06-09 23:59:58 | 2018-06-10/1/002(00000005)/00    |
| 2018-06-10 00:00:00.045 | 4641      | 2018-06-09 23:59:56 | 2018-06-09/1/343157(00717202)/00 |
| 2018-06-10 00:00:00.045 | 4641      | 2018-06-09 23:59:56 | 2018-06-10/1/001(00000002)/00    |
| 2018-06-10 00:00:00.572 | 9458      | 2018-06-09 23:59:57 | 2018-06-09/1/343160(00717207)/00 |
| 2018-06-10 00:00:00.572 | 9458      | 2018-06-09 23:59:57 | 2018-06-10/1/004(00000007)/00    |
| 2018-06-10 00:00:00.014 | 9499      | 2018-06-09 23:59:57 | 2018-06-09/1/343156(00717201)/00 |
| 2018-06-10 00:00:00.014 | 9499      | 2018-06-09 23:59:57 | 2018-06-10/1/000(00000001)/00    |
+-------------------------+-----------+---------------------+----------------------------------+

この経路情報をダブりデータで比較してみると、連続する2つの日付の、ちょうど境界あたりに分布していることがわかります。ここまでくると、ダブりの原因は、日付ごとにログファイルを分ける処理にある可能性が高いと考えるのが妥当でしょう。

原因は AWS API CloudWatch Logs CreateExportTask の仕様誤認+だった

今回ETL処理のインプットとなったログファイルは、AWS CloudWatch Logsに出力されたログを定期的にエクスポートしてS3へ保存させたものです。このエクスポート処理の設定は定時ジョブで実行しており、以下のようになっています。

client = boto3.client('logs')
response = client.create_export_task(
    logGroupName      = log_group_name,
    fromTime          = from_ts * 1000,
    to                = to_ts * 1000,
    destination       = s3_bucket_name,
    destinationPrefix = s3_prefix
)

from_ts と to_ts はちょうど24時間(=86400秒)離れています。一見良さそうですが、この種の境界設定については、常に「inclusive(指定値を含む)」なのか「exclusive(指定値は含まない)」かを注意する必要があります。以下のURLからAPIの仕様を確認してみましょう。

https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_CreateExportTask.html

Request Parameters

  • from
    • The start time of the range for the request, expressed as the number of milliseconds after Jan 1, 1970 00:00:00 UTC. Events with a time stamp earlier than this time are not exported.
  • to
    • The end time of the range for the request, expressed as the number of milliseconds after Jan 1, 1970 00:00:00 UTC. Events with a time stamp later than this time are not exported.

否定形で書かれていますが、本質的には inclusiveです。 つまり、ちょうど24時間分(=86400000ミリ秒)離れた2つの値をtoとfromに指定した場合、1ミリ秒分はダブる ということです。この点については、不注意だったと言えます。

原因がわかりました!と言いたいところですが、あれ?何かおかしいですよね。ダブりデータは「2018-06-10 00:00:00.045」から「2018-06-10 00:00:00.572」に分布していたのです。1ミリ秒ではなく、1秒ですね。結局AWSのこのAPI、ミリ秒指定と言っておきながら、ミリ秒部分は評価していないようです。

上記のAPIリファレンスの文章に当てはめてみましょう。2018-06-09のログファイルについて、

from: Events with a time stamp earlier than 2018-06-09 00:00:00.000 are not included.
to: Events with a time stamp later than 2018-06-10 00:00:00.000 are not included.

となっているわけですが、実際には 2018-06-10 00:00:00.000 から、少なくとも2018-06-10 00:00:00.572 までのログが、入ってしまっているわけです。 ミリ秒単位で指定させておきながら、これはひどいよな、と思います。

ExclusiveにすればOK、なのか?

AWSAPI仕様はわかりました。では、以下のようにエクスポート設定コードを改めればOKでしょうか?

client = boto3.client('logs')
response = client.create_export_task(
    logGroupName      = log_group_name,
    fromTime          = from_ts * 1000,
    to                = (to_ts * 1000) - 1,
    destination       = s3_bucket_name,
    destinationPrefix = s3_prefix
)

つまり、2018-06-09のログファイルについては以下のような指定になるわけです。

from: Events with a time stamp earlier than 2018-06-09 00:00:00.000 are not included.
to: Events with a time stamp later than 2018-06-09 23:59:59.999 are not included.

筆者は、これは危険な設定だと思います。今度はエクスポートの欠損が起こる可能性があるからです。 例えば、CloudWatch Logsにログが 2018-06-09 23:59:59.9995 に到着したら、取りこぼされてしまいます。

では、本当に23:59:59.9995などというタイミングでログが到着したという事象が発生するのでしょうか?

以下のCloudWatch Logsログ取得APIの仕様によると、

https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_GetLogEvents.html

https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html

ログの収録時刻(ingestionTime)は「ミリ秒単位の整数」となっていますので、23:59:59.9995は、23:59:59.999か、翌日00:00:00.000に丸められるでしょうから、現時点では大丈夫そうではあります。

しかし現在巷で使用されているハードウェアクロックの時間分解能は1ナノ秒となっており、AWS CloudWatch Logsがミリ秒よりさらに細かい到着時刻記録をサポートした場合、取りこぼしの心配が生じる可能性があります。(あくまで仕様上の話ですが。。。)

筆者の結論としては、このエクスポート設定コードは、このままにしておくことにしました。 データの受信記録が永久的に失われるというのは非常に恐ろしい出来事ですので、潜在的な危険はできるだけ排除したい。それなら多少の手間をかけ、後から重複を除去した方がマシ、だと思ったのです。

これで終わり、ではなかった!

これでダブりデータの原因は特定されました。安心して眠れそうです。。。しかし、本当にそうなのでしょうか…?

疑い深い筆者は、今度は「00:00:00.000 ~ 00:00:00.999 以外の時間帯のダブりデータ」を探してみました。そして。。。見つけてしまったのです。

+-------------------------+-----------+---------------------+---------------------------------+
|         dt_log          | device_id |     device_time     |          log_file_pos           |
+-------------------------+-----------+---------------------+---------------------------------+
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:36:54 | 2018-06-12/2/65245(00158574)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:37:00 | 2018-06-12/2/65258(00158587)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:37:00 | 2018-06-12/2/65244(00158573)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:37:03 | 2018-06-12/2/65246(00158575)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:37:03 | 2018-06-12/2/65250(00158579)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:36:54 | 2018-06-12/2/65248(00158577)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:36:57 | 2018-06-12/2/65257(00158586)/00 |
| 2018-06-12 14:37:31.449 | 4896      | 2018-06-12 14:36:57 | 2018-06-12/2/65247(00158576)/00 |
| 2018-06-13 00:44:05.565 | 2164      | 2018-06-13 00:43:57 | 2018-06-13/2/61588(00078056)/00 |
| 2018-06-13 00:44:05.565 | 2164      | 2018-06-13 00:43:57 | 2018-06-13/2/61587(00078055)/00 |
+-------------------------+-----------+---------------------+---------------------------------+

このダブりはこれまで特定した原因だけでは説明できません。一体何が起こったのか、筆者は元ログを調査しました。その結果、同時刻に同一データの到着が2回記録されていることを発見してしまいました。

158575  2018-06-12 23:37:31.449 : trackingProc len:36 data:4dxxxx...
158579  2018-06-12 23:37:31.449 : trackingProc len:36 data:4dxxxx...
※ ここでは時刻はデバイスからのデータを受信するインスタンスのシステム時刻で、JSTで書かれている。

そんなばかなと思ってログファイルのエクスポート元のAWS CloudWatch Logsもクエリしてみましたが、上記の2行のログは、全く同時刻に到着しています。

$ aws logs get-log-events --cli-input-json "`cat query_aws_logs.json`" --profile=xxxx | jq -r '.events[]|select(.message | contains("4dxxxx..."))|.ingestionTime'
1528814254774
1528814254774

次はネットワーク通信ログを、と言いたいところですが、残念ながらここまでは記録していませんでした。どこかで想定外の重複動作があったのでしょうが、真実はやぶの中です。原因が特定できないので対策方針が立つわけもなく、データクレンジングで対処するしかありません。今回の場合は同一デバイス・同一時刻に発生する物理事象はひとつに決まっていますから、ダブりデータのうちひとつだけを採用すれば良いでしょう。

この類の現象にどんな姿勢で臨めば良いのか

ここまでくると、「もう何を信じて良いやら」という気持ちになってきました。結局ログの記録、転送のそれぞれの段階で、ぴったり完璧とは行かない例外事象が起こってしまっているのです。そしてマニュアルも厳密でなく、オーナーシップがあるわけでもないので仕様は変わる。こういう状態でデータ分析をやるときは、いかなるポリシーを定めて事に取りかかればいいのでしょうか?

筆者の結論は以下のようなものです。

  • まず原理的に、分散環境でデータ転送する時は、「消えてもいいから最大1回(at most once)」「消えないがダブる可能性あり(at least once)」の2択。
  • そしてデータが途中で消えるのは困るので、ダブりを許容するしかない。
  • ダブりは、最後に洗い落とすしかない。

プログラムコードのデバッグにも似た対策措置が、データに対しても必要なようです。

最後までお読みいただき、ありがとうございました。

Cloud Vision APIでWebサイトを比較する

みなさんこんにちは。エンジニアの佐藤です。今回はCloud Vision APIの活用について書かせていただきたいと思います。

モチベーション

先日の Google I/O 2018 で、チャットボットが電話をかけて音声で美容室を予約するデモがあり、先進的事例として話題になりました。こうなると「この種の単純作業はAIに置き換わり、失業が社会問題になるのではないか。」という不安が募ります。しかし筆者の知っている範囲では、コンピュータの認識能力の柔軟性は、未だ人間には遠く及ばないと思います。 ただし、現時点で既に人間が追い越されている特性もあると思います。それは スピードと評価の安定性です 。24時間休みなく多数の画像判断を完全に一定の基準で実行することは、人間にはできません。しかしコンピュータは十八番です。 今回はこの特性を評価して、 Webサイトの画像全部の総合評価とWebサイト間の比較 を試みたいと思います。

筆者が選んだのは、大手リテールサイトのR社とA社です。どちらもホームページには100枚以上の商品などの画像があり、商品ジャンルも多岐にわたっています。 比較しようにも、評価観点が定まりそうにありません。そこで、これらの画像を全部、Cloud Vision APIでラベル検出させてみます。

道具立て

最初に両サイトの画像を個別ファイルとして保存し、次にそれぞれのファイルをCloud Vision APIでラベル検出させます。 結果はすべてPostgresqlに保存し、SQL言語でクエリして評価します。

Cloud Vision APIの結果

ラベル検出の仕様は以下のサイトに書かれていますが、

https://cloud.google.com/vision/docs/labels そのレスポンスは以下のように、「何が」「どのくらい確からしく」写っていたのかを答えてくれるというものです。

"labelAnnotations": [
    {
        "topicality": 0.9604079,
        "score": 0.9604079,
        "mid": "/m/01bqk0",
        "description": "bicycle wheel"
    },
    {
        "topicality": 0.9501146,
        "score": 0.9501146,
        "mid": "/m/019sc",
        "description": "black"
    },
    ...
    {
        "topicality": 0.58060855,
        "score": 0.58060855,
        "mid": "/m/0h8n8m2",
        "description": "ventilation fan"
    },
    ...

この通りレスポンスには複数のラベルが返され、色や形状など、様々な観点が含まれています。この場合は黒色の卓上クリップ扇風機なのですが、認識結果として最も正しいのは最もscoreの低い「ventilation fan」です。(やはり単発では、コンピュータは人間にはかなわないのです。)

なお、ラベル検出を行う場合は、追加料金を払うことなく「セーフサーチ」チェックも仕掛けることができます。これはアダルト画像などを検出するもので、上記の卓上クリップ扇風機の写真の場合は、以下のような結果になります。

"safeSearchAnnotation": {
    "violence": "VERY_UNLIKELY",
    "racy": "VERY_UNLIKELY",
    "adult": "VERY_UNLIKELY",
    "medical": "VERY_UNLIKELY",
    "spoof": "VERY_UNLIKELY"
}

セーフサーチについては、以下のサイトに仕様が書かれています。 https://cloud.google.com/vision/docs/other-features#safe_search

結果

一応計数してみましょう。

  • 総画像数: 522
  • 検出されたラベルの総数: 4917
  • 検出されたラベルの種類: 661

661種類、4917個ものラベル検出があったわけですが、この結果をどうやって取りまとめたものでしょうか?

一番単純な方法は、「ラベルごとにスコアを加算する」やり方です。これをサイト画像全体について集計すると、どんな画像が多いのかを摑むことができそうです。以下のような結果になりました。

        url        |   label         |      score
-------------------+-----------------+------------------
 www.ra*****.co.jp | product         |     249.13065277
 www.ra*****.co.jp | font            |     178.09255501
 www.ra*****.co.jp | text            |     174.66525343
 www.ra*****.co.jp | line            |     115.06299671
 www.ra*****.co.jp | brand           |     112.54623938
 www.ra*****.co.jp | logo            | 96.9688526700001
 www.ra*****.co.jp | graphics        |      87.28768391
 www.ra*****.co.jp | black           |       82.1643062
 www.ra*****.co.jp | black and white |      79.13861794
 www.ra*****.co.jp | monochrome      |      54.89684521
(10 rows)

       url        | label       |    score
------------------+-------------+-------------
 www.am****.co.jp | product     | 203.6307481
 www.am****.co.jp | font        | 44.40389657
 www.am****.co.jp | text        | 32.15153994
 www.am****.co.jp | brand       | 30.75662519
 www.am****.co.jp | technology  | 22.13816894
 www.am****.co.jp | line        | 17.98218844
 www.am****.co.jp | yellow      | 13.99654375
 www.am****.co.jp | black       | 13.39340801
 www.am****.co.jp | hardware    | 12.35800936
 www.am****.co.jp | sleeve      | 12.21443735
(10 rows)

結果は両サイトでよく似ています。両サイトともリテールサイトですから、「product」や「brand」が上位に来るのは当然です。また、画像の中には商品画像だけでなく、Webサイト自身のフレームやアイコンも多量に含まれている他、商品写真にも文字が埋め込まれているものが多数あります。このため「font」「text」「line」や色名も共通で上位に入っています。

強いて傾向を指摘するとすれば、R社の「logo」と、A社の「technology」です。R社のサイトが企画サイトへのポータルサイトの機能を重視したデザインになっているのに対し、A社のサイトは家電の写真が大写しになっていました。このような大雑把なやり方でも、少しは両サイトの傾向の違いが出ていると言えるのではないでしょうか。とは言え、もう少しなんとかならないでしょうか。

次に思いついた方法は、サイトごと、各ラベルごとに1~100までの相対スコアを計算し、これを相互に比較する方法です。例えばあるサイトで最も合計スコアの高いラベルには100を、最も合計スコアが低いラベルには0を設定します。ラベルごとに突き合わせれば、片方のサイトで扱いの小さい(または無い)ラベルが他方のサイトでは大きく取り上げられている、などの傾向がわかるかもしれません。

この結果はなかなか興味深いものとなりました。以下に抜粋します。

                description                | r_rel_score | a_rel_score | rel_score_diff 
-------------------------------------------+-------------+-------------+----------------
 bottled water                             |             |          81 |            -81
 toy                                       |          10 |          87 |            -77
 electronics accessory                     |          23 |          92 |            -69
...

 clothing                                  |          93 |          94 |             -1
...
 product                                   |         100 |         100 |              0
...

 recipe                                    |          90 |          10 |             80
 hair coloring                             |          91 |             |             91

今度ははっきり以下の傾向が見て取れます。

  • A社のみ: bottled water
  • A社多い: toy, electronics accessory
  • 同じ: clothing, product
  • R社多い: recipe
  • R社のみ: hair coloring

確かにA社のサイトには、ミネラルウォーターとおもちゃが多いのです。また両サイトとも衣料品がかなりのスペースを占めています。更に、この時のR社サイトには食材販売企画の広告が多く、これが「recipe」と認識されたと考えられます。 水とおもちゃ・家電重視のA社と、食品と美容重視のR社という傾向が、かなりはっきりと抽出されました。

セーフサーチの結果

今回は大手リテール業者のトップサイトのため、セーフサーチで問題が指摘された画像はほとんどありませんでした。 しかし、ただひとつ、 「adult = POSSIBLE」となった商品があり、それは「目元エステ家電」でした 。商品紹介画像では女性が仰向けになって分厚いアイマスクのような商品を装着していたので、誤解されてしまったようです。

しかしこの指摘、わからないでもありません。今回評価した画像の中ではこの画像以上に指摘されそうな画像はありませんでしたので、これはこれで正しい評価と言えます。

終わりに

Cloud Vision APIは既成のモデルを使用しますので、ラベルの結果については受け入れるしかありません。 しかし、もう少し使い方のノウハウが蓄積できれば実用になりそうだ、というのが筆者の感想です。 既成AIサービスを効果的に使うには、それなりの経験を積む必要があるのかもしれません。

最後までお読みいただき、ありがとうございました。