はじめまして、CI事業部の山本です。
初めての投稿です。
簡単に自己紹介いたしますと、エンジニアとしてフロントエンドとバックエンド両方書いています。
最近だとVue + Ruby on Railsで開発し、AWS ECSをFargate上で動かしています。
そのため、今回のreInventではコンテナ技術、特に来るべきTokyoリージョンでのEKSに備えてKubernates関連のセッションを中心に聞いています。
フレクトが行く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コンテナで実装した仮想デスクトップサーバーです。
この開発環境、少し前に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画面に表示される、というものです。 図に描くとこんな感じです。
報告された問題現象とは、ブラウザが10秒ほど応答停止したのちに、エラーが画面に表示されるというものです。エラーの内容から、筆者は、Salesforceがまともなレスポンスを受け取っていないんだろうと推測しました。そして10秒ブロックですから、一連のリクエスト連鎖のどこかでタイムアウトしたんだろうと思いました。筆者は外部システムAのログを観察しました。すると。。。外部システムSをリクエストする直前のログを最後に足取りが途絶えていました。
きっとSalesforceからシステムAへのリクエストが10秒でタイムアウトし、Visualforceページのエラーへとつながっていったのでしょう。
図に描くとこんな感じです。
システムSは「シロ」
次に筆者が疑ったのは、システムSです。実はシステムSは今回の機能開発に合わせて平行開発されたもので、開発中は多少問題があったこともあったのです。筆者はシステムAの内部から、Pythonの即席コードでシステムSにリクエストしてみました。すると。。。何の問題もなくレスポンスがあります。
原因は「聞か猿」ではなく「言わ猿」
「他人を最初に疑うのは良くないよな」と反省した筆者は、問題現象発生時のパケットキャプチャを採取することにしました。すると。。。システムSへのリクエストはそもそも送信されていないことがわかりました。そんなバカなと思って2度3度やってみましたが、結果は変わりません。技術者たる者、事実の前には謙虚でなくてはなりません。 リクエストがタイムアウトしたのではなく、そもそもリクエストしていなかったのです。
ここで筆者は困ってしまいました。というのも、このシステムA、他にも似たような処理を常時続けており、そちらには何の問題もないからです。DockerコンテナのJava実装された単一のプロセスで、あっちはよくてこっちはダメという状態なのです。システムAからリクエスト可能であることは、図3で確認されていますから、原因はシステムA側にあるはずです。
リブートで回復するが、再び発生
筆者はこの段階で、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キープアライブも設定されていなければ(今回は設定されていない)、そのような催促はない。永久待機です。
疑い深い筆者は、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秒後にソケットをクローズしたにも関わらず、クライアント側では受信待機のソケットが、「来ぬ人を」待ち続けています。
タイムアウトを設定し、問題現象は解決へ
ここまで来ると受信待機ソケットの滞留を防止する方法は、タイムアウト設定ということになります。筆者は以下のようにタイムアウトを設定しました。
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ライブラリもJavaのApache 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」の中から選択します。
こうして作成したAVDを起動すると。。。ありゃ、エラーです。
/dev/kvm のアクセス権が無いと言われてしまったので、このデバイスのオーナーをAVDの実行ユーザーに変えました。
sudo chown user1.user1 /dev/kvm
再度AVDを起動すると。。。動きました!この速度、確かにハードウェア仮想化の速さです。
試しにHello Worldを動かしてみると、ローカル環境同様に開発アプリがAVDにロードされました。
使えるの?
ようやく念願の「クラウド仮想デスクトップ+AVD」が実現したのですが、その性能はいかほどのものでしょうか。正直に言いますと、 「耐えられないほどではないが、かなり遅い」というのが筆者の正直な印象です。
ハードウェア仮想化を有効にしてもなお遅い理由として、仮想デスクトップなのでグラフィックのハードウェア支援が一切無いことが原因として考えられます。特にスマホアプリはアニメーションを多用し、通常は中間フレームはハードウェア支援で描画しますので、これを全部CPUでこなして、かつ、ネットワークで転送しなければならないというハンディが動作を遅くしていることは容易に想像できます。
ですが、全てのアプリケーションが常時激しいアニメーションを行うわけではないと思いますので、これは使い方次第なのではないでしょうか。
もう一つの問題として、AVDが多量のリソースを消費することがあります。図はAVDの実行中にtopコマンドでメモリ消費を調べたものですが、3GBを超えるメモリが使われています。
今時のスマホの性能を考えると仕方がないのかもしれませんが、しかし、この点についてはクラウドですし、メモリも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、なのか?
AWSのAPI仕様はわかりました。では、以下のようにエクスポート設定コードを改めれば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択。
- そしてデータが途中で消えるのは困るので、ダブりを許容するしかない。
- ダブりは、最後に洗い落とすしかない。
プログラムコードのデバッグにも似た対策措置が、データに対しても必要なようです。
最後までお読みいただき、ありがとうございました。