fluent-plugin-bigqueryでログの書き込みが痕跡なく欠損するケースがある問題
fluent-plugin-bigqueryを使ってBigQueryにStreaming Insertでログを書き込む時に、
痕跡なくログが欠損するケースがあるのでは? という話です。
fluent-plugin-bigqueryでのログの書き込み処理/エラー処理はこのようになっています。
res.success?
がtrueであればエラーはなく書き込みが成功しているという想定。
falseの時にはレスポンスのjsonのerrorエラーの中身を見て、ログを吐くなどのエラー処理をするようです。
res = client().execute( api_method: @bq.tabledata.insert_all, parameters: { 'projectId' => @project, 'datasetId' => @dataset, 'tableId' => table_id, }, body_object: { "rows" => rows } ) unless res.success? # api_error? -> client cache clear @cached_client = nil res_obj = extract_response_obj(res.body) message = res_obj['error']['message'] || res.body if res_obj if @auto_create_table and res_obj and res_obj['error']['code'] == 404 and /Not Found: Table/i =~ message.to_s # Table Not Found: Auto Create Table create_table(table_id) raise "table created. send rows next time." end end log.error "tabledata.insertAll API", project_id: @project, dataset: @dataset, table: table_id, code: res.status, message: message raise "failed to insert into bigquery" # TODO: error class end
ではres.success?とはどのような処理かというとこちら。
BigQueryのAPIのレスポンスコードをみて400系以上でなければtrueが返る仕様のようです。
## # Check if request failed # # @!attribute [r] error? # @return [TrueClass, FalseClass] # true if result of operation is an error def error? return self.response.status >= 400 end ## # Check if request was successful # # @!attribute [r] success? # @return [TrueClass, FalseClass] # true if result of operation was successful def success? return !self.error? end
https://github.com/google/google-api-ruby-client/blob/v0.8.3/lib/google/api_client/result.rb#L81-L99
BigQueryの挙動を検証していると、レスポンスコードが20Xであるにもかかわらず、
レスポンスのjsonに、特定の行でエラーが含まれることがありました。
そのようなケースでは、fluent-plugin-bigqueryではログが欠損してしまいます。
(この問題だけでなく他のいろいろな経緯から、) 実運用ではfluent-plugin-bigqueryを使うのをやめ、
自前でワーカーを作り以下のようなエラー処理をして運用をはじめました。
エラーになった場合にはエラーの内容を見てリトライをかけるようにしています。
# @gclient = Google::APIClient.new( .. ) # @bq_api = @gclient.discovered_api("bigquery", "v2") # result = @gclient.execute( :api_method => @bq_api.tabledata.insert_all .. ) def check_result(result, data) unless result.success? @logger.warn "Insert failed partically. (API call)" JSON.parse(result.body)["error"]["errors"].each do |error| @logger.warn "Error is #{error["message"]}" end @retryable = true return false end errors = check_result_errors(result.body) unless errors.nil? @logger.warn "Insert failed partically. (some rows)" @logger.warn "Error is #{errors}" @logger.warn "Error data #{data[0]}" @retryable = retryable?(errors) return false end @logger.debug "Insert successes. (rows:#{data.size})" return true end def check_result_errors(body) body = JSON.parse(body) return nil if body["insertErrors"].nil? errors = [] body["insertErrors"].each do |error| errors += error["errors"].inject([]){|x, e| x << e["reason"]} end return errors.uniq end def retryable?(errors) return false if errors.include?("invalid") true end
と、ここまでが去年くらいの話。
すると、今日TwitterのタイムラインでBigQueryのログの欠損の話があがっていたのを見かけてこの話を思い出しました。
しばらく間があいたので、状況が変わってるかなと思いしらべてみたけど改善されてはいない模様。
ちなみに、簡単に該当状況が起こる再現コードを書くとこんな感じ。
project_id = "PROJECT_ID" dataset_id = "test" table_id = "test" # schema col1:STRING, col2:INTEGER rows = [ {"json"=> {"col1" => "string", "col2" => 1}}, {"json"=> {"col2" => "string", "col2" =>"string"}}, ] # @gclient = Google::APIClient.new( .. ) # @bq_api = @gclient.discovered_api("bigquery", "v2") # result = @gclient.execute( :api_method => @bq_api.tabledata.insert_all .. ) result = @gclient.execute( :api_method => $bq_api.tabledata.insert_all, :parameters => { 'projectId' => project_id, 'datasetId' => dataset_id, 'tableId' => table_id, }, :body_object => { "rows" => rows } ) puts result.success? # => true puts result.body # => # { # "kind": "bigquery#tableDataInsertAllResponse", # "insertErrors": [ # { # "index": 1, # "errors": [ # { # "reason": "invalid", # "location": "Field:col2", # "message": "Could not convert value to integer (bad value or out of range)." # } # ] # }, # { # "index": 0, # "errors": [ # { # "reason": "stopped" # } # ] # } # ] # }
正直fluent-plugin-bigqueryの問題と言うよりは、
google-api-client もしくは BigQueryのAPIの仕様の問題という気がするので、プラグイン側にIssueを立てたりするわけでもないんですが、
痕跡なくログの欠損がおきてしまうとまずいという環境で使っている方は注意したほうがいいかなと思います。
追記(2015/12/02 18:40): 案の定すでにPRがあった。 https://github.com/kaizenplatform/fluent-plugin-bigquery/pull/38
OpenSCAPの検証/実用編
前回の記事でOpenSCAPの概要と、簡単な使い方については理解できたので、
今回は実用的な使い方について調査してみました。
SCAPを利用する上で最も重要なのが、どんなSCAP content(スキャンのポリシ)を利用するかだと思います。
SCAP contentは自分で構築することもできますが、
効果的/網羅的なポリシを自分で作り、メンテナンスし続けるのはなかなか骨の折れる作業だと思います。
ということで、今回はThe SCAP Security Guide project(以下SSG, https://fedorahosted.org/scap-security-guide/)で提供されている
SCAP contentを使ってスキャンするときの手順をまとめます。
SCAP contentの取得
SSGが提供するSCAP contentは、RPMでインストールもしくはGitHubから取得することができます。
今回はより新しいポリシが取得できるように、GitHubから取得することにします。
# wget -O scap-security-guide.zip "https://github.com/OpenSCAP/scap-security-guide/releases/download/v0.1.24/scap-security-guide-0.1.24.zip" # unzip scap-security-guide.zip
SCAP contentの確認
解答したファイルの中身を確認します。
# cd scap-security-guide-0.1.24/ # ls Contributors.md kickstarts ssg-centos7-ds.xml ssg-firefox-ds.xml ssg-rhel7-ds.xml ssg-sl7-ds.xml LICENSE ssg-centos5-ds.xml ssg-chromium-ds.xml ssg-rhel5-ds.xml ssg-sl5-ds.xml ssg-webmin-ds.xml README.md ssg-centos6-ds.xml ssg-fedora-ds.xml ssg-rhel6-ds.xml ssg-sl6-ds.xml
解答したファイルの中身を見ると、XXX-ds.xmlというファイルが複数入っているのがわかります。
どんなファイルなのか、oscap infoコマンドで確認してみます。
今回作業する環境はScientific Linux 6なので、ssg-sl6-ds.xmlを利用します。
# oscap info ssg-sl6-ds.xml Document type: Source Data Stream Imported: 2015-07-08T18:36:48 Stream: scap_org.open-scap_datastream_from_xccdf_ssg-rhel6-xccdf-1.2.xml Generated: (null) Version: 1.2 Checklists: Ref-Id: scap_org.open-scap_cref_ssg-rhel6-xccdf-1.2.xml Profile: xccdf_org.ssgproject.content_profile_CS2 Profile: xccdf_org.ssgproject.content_profile_common Profile: xccdf_org.ssgproject.content_profile_server Profile: xccdf_org.ssgproject.content_profile_stig-rhel6-server-upstream Profile: xccdf_org.ssgproject.content_profile_usgcb-rhel6-server Profile: xccdf_org.ssgproject.content_profile_rht-ccp Profile: xccdf_org.ssgproject.content_profile_CSCF-RHEL6-MLS Profile: xccdf_org.ssgproject.content_profile_C2S Profile: xccdf_org.ssgproject.content_profile_pci-dss Checks: Ref-Id: scap_org.open-scap_cref_ssg-rhel6-oval.xml Ref-Id: scap_org.open-scap_cref_output--ssg-rhel6-cpe-oval.xml Ref-Id: scap_org.open-scap_cref_output--ssg-rhel6-oval.xml Dictionaries: Ref-Id: scap_org.open-scap_cref_output--ssg-rhel6-cpe-dictionary.xml
重要なのは Document type: Source Data Stream
の部分です。
前回の記事では、OVALファイルやXCCDFファイルを使ったスキャンの実行を行いましたが、
今回はこのSource Data Streamファイルを使ってスキャンを行います。
DataStreamについての解説は、以下のページに詳しく載っています。
http://martin.preisler.me/2012/12/introduction-to-scap-datastreams-with-openscap/
スキャンの実行
今回利用するSource Data Streamファイルは、OVALとXCCDFのコンテンツをどちらも含むので、
それぞれスキャンを実行します。
OVAL
(今回は--reportだけでよいのだが、ovalの場合--resultを付けないと何故か--reportのファイルが生成されなかった。要調査。)
# oscap oval eval --results reports/ssg-oval.xml --result reports/ssg-oval.xml --report reports/ssg-oval.html ssg-sl6-ds.xml Definition oval:ssg:def:998: false Definition oval:ssg:def:996: false .. snip .. Definition oval:ssg:def:1001: true Definition oval:ssg:def:100: false Evaluation done.
XCCDF
# oscap xccdf eval --profile xccdf_org.ssgproject.content_profile_common --report reports/ssg-xccdf.html ssg-sl6-ds.xml Title Ensure /tmp Located On Separate Partition Rule xccdf_org.ssgproject.content_rule_partition_for_tmp Ident CCE-26435-8 Ident DISA FSO RHEL-06-000001 Result fail .. snip .. Title Require Client SMB Packet Signing, if using mount.cifs Rule xccdf_org.ssgproject.content_rule_require_smb_client_signing_mount.cifs Ident CCE-26792-2 Ident DISA FSO RHEL-06-000273 Result pass
ポリシの調整
前述の手順で出力された結果を確認して、
必要なポリシのresultがpass/trueになるように設定変更を行います。
また、運用の都合上不要なチェックは外してしまいましょう。
おそらくこの精査が一番大変なところだと思います。
Source Data Stream(ssg-sl6-ds.xml)の以下の部分を編集することでチェックをスキップすることができます。
(どちらか片方だけではスキップできなかった。なぜそうなるのか要確認。)
- <nsX:select idref="XXX" selected="true" /> + <nsX:select idref="XXX" selected="false" />
- <nsX:Rule id="XXX" selected="true" severity="low"> + <nsX:Rule id="XXX" selected="false" severity="low">
このポリシの有効化/無効化作業をoscapコマンドでよしなにやれるとよいのですが、
そのような手段は提供されていないようです。
今回の検証を行ってみて
- SSGのSCAP Contentを使うことで、手軽にCCEベースのポリシのチェックができるようになります。
- 本来やりたかったのはCVEベースのチェックなので他のポリシを探す必要がありそうです。
- Source Data Streamの編集は、手でやろうとすると大変なのでよしなにXMLを編集できるプログラムを用意するとよさそうです。
- (少なくともSSGのポリシでは)いくつかの注意が必要そうです。
OpenSCAPの検証/導入編
SCAPとは
- SCAP(Security Content Automation Protocol)とはNISTによって管理されている規格。
- エンタープライズシステムのセキュリティメンテナンスの標準化のためにつくられたもの。
- パッチの存在確認の自動化
- システムのセキュリティ設定の確認
- 不正アクセスの痕跡の調査
- ...等
OpenSCAPとは
- SCAPの構成要素は脆弱性や設定等のセキュリティデータを伝えるための、複数の複雑なデータ変換フォーマットを含む。
- 歴史的な理由から、これらの情報に適切なフォーマットで問い合わせをするツールはほとんどなかった。
- そのようなツールの欠落は、SCAPを使ってもらうことの障壁になっていた。
- OpenSCAPプロジェクトは、SCAPへのアクセシビリティを向上させることを目的としている。
- OpenSCAPは、以下のコンポーネントで構成される。
- 以下の仕様書をサポート
- XCCDF: The Extensible Configuration Checklist Description Format (ver. 1.2)
- OVAL®: Open Vulnerability and Assessment Language (ver. 5.11)
- Asset Identification (ver. 1.1)
- ARF: Asset Reporting Format (ver. 1.1)
- CCE™: Common Configuration Enumeration (ver. 5.0)
- CPE™: Common Platform Enumeration (ver. 2.3)
- CVE®: Common Vulnerabilities and Exposures
- CVSS: Common Vulnerability Scoring System (ver. 2.0)
- OpenSCAPは、SCAPの仕様に含まれない機能も実装している。
OpenSCAPの使い方
インストール
ソースコードによるコンパイル もしくは 使用しているLinuxディストリビューションに合わせた既存のビルドを使うことができます。
今回はCentOS6系による検証なので、yumを使ってインストールします。
$ sudo yum install openscap-utils openscap-content $ rpm -qa | grep openscap openscap-0.9.3-1.el6.x86_64 openscap-content-0.9.3-1.el6.noarch openscap-utils-0.9.3-1.el6.x86_64
使い方
SCAP Contentの情報表示
oscap infoを使うと、OVALファイルやXCCDFファイルのようなSCAP Contentの情報を確認できます。
$ oscap info scap-rhel6-oval.xml Document type: OVAL Definitions OVAL version: 5.8 Generated: 2011-03-06T12:00:00-04:00 Imported: 2012-12-13T00:09:05
$ oscap info scap-rhel6-xccdf.xml Document type: XCCDF Checklist Checklist version: 1.1 Status: draft Generated: 2011-10-12 Imported: 2012-11-15T21:10:41 Resolved: false Profiles: RHEL6-Default
スキャン
XCCDFによるスキャンを行います。
今回は以下の手順を参考に、Red Hatのセキュリティチームが提供してくれているOVALファイル, XCCDFファイルを使います。
http://www.open-scap.org/page/Documentation#How_to_run_vulnerability_scan_on_Red_Hat_Enterprise_Linux
- OVALファイル, XCCDFファイルの取得
$ wget http://www.redhat.com/security/data/metrics/com.redhat.rhsa-all.xccdf.xml $ wget http://www.redhat.com/security/data/oval/com.redhat.rhsa-all.xml
- スキャンの実行
# oscap xccdf eval --results results-xccdf.xml --report report-xccdf.html com.redhat.rhsa-all.xccdf.xml # oscap oval eval --results results-oval.xml --report report-oval.html com.redhat.rhsa-all.xml
--resultsオプションを付けてスキャンを実行すると、結果のXMLファイルが生成されます。
スキャンの結果を機械的に利用したい場合には、このオプションを使うといいでしょう。
--reportオプションを付けてスキャンを実行すると、結果のHTMLファイルが生成されます。
人間が確認する場合には適当なウェブサーバを立ち上げる等してこのHTMLファイルを見るといいでしょう。
尚、レポートは、以下のようなフォーマットで出力されます。
https://mpreisle.fedorapeople.org/openscap/report-xccdf.html
https://mpreisle.fedorapeople.org/openscap/report-oval.html
以上、OpenSCAPの説明と簡単な使い方の説明でした。
OSCON 2015 参加レポート
7/20 ~ 7/24にPortlandのOregon Convention Centerで開催されたOSCON 2015に参加してきました。
(尚、僕が参加したのは7/21 ~ 7/24です。)
OSCONはO'Reilly主催でオープンソースがテーマのカンファレンスです。
今年は今までで最大の参加者数だったそうです。
(メモしてなかったので詳しい人数は忘れたけど4000人超えだったかな?)
僕が参加の準備をするにあたってあんまり日本語の情報が見つからなかったので、
来年以降に参加する人のためにメモを残しておこうと思います。
(もちろんすべての情報が来年も役立つとは限りません)
Tutorials & Session
- 全日程を通して、約20の部屋を使って行われました。
- Tutorialは210分, Sessionは40分で行われました。
- Tutorialはカンファレンスの登録時に予めなにを受講するか予約しておきます。(名前とかは確認はされなかったのでどれでも聞けそうな雰囲気はあった)
- 各Sessionの間は10分しかない上に、時間をオーバーするセッションもあったので予め何を聞くか決めておかないとけっこう大変です。
- 内容的にはオープンソースの文化や(広義での)技術に対する考え方の話が半分、特定の技術に関するtipsみたいな話が半分くらいの印象でした。
- トレンドとしてはContainer, Microservice系のSessionが多く、人もたくさん集まっていました。
- Sessionのスライドは以下にアップロードされています。
- Sessionの動画はイベント終了後3週間後を目安に閲覧できるようになるそうです。(Platinum or Goldパスの参加者 もしくは $999を別途支払い)
Expo
- 3日目 ~ 4日目で、各企業による展示が行われました。
- HP, IBMのようなベンダが、どのようにオープンソース界隈で活動しているかを大々的にアピールしていたのが印象的でした。
- IBM Bluemix (https://bluemix.net) - アプリケーションを構築、管理、実行するためのプラットフォーム
- HP Helion (http://www8.hp.com/jp/ja/cloud/helion-overview.html) - OpenStackの商用ディストリビューション
- あとはCloudFederationサービス, モニタリングサービス, IoTあたりをやっている企業が多かったです。
会場
- 会場のOregon Convention Centerは、MAX(現地のライトレール)のConvention Center駅が最寄りです。
- MAXのRed Line, Blue Line, Green Lineが停まります。空港からだとRed Lineで行けます。
- 念のためモバイルルータも用意していましたが、OSCON用に会場で提供されている無線LANは特に不自由することなく使えました。
- 各セッションルームにはいくつかの椅子の下にコンセントが用意してあり、バッテリーに困ることはありませんでした。
- 朝はコーヒーとフルーツ, 昼はビュッフェ形式の食事, 午後のセッションの合間で軽食が提供されました。
- Portlandの気候は東京と同じくらい(東京よりちょっと涼しかった)だが、会場は冷房強くて寒かった。初日は知らずに薄着だったので凍えた。
その他
■
"お前もう新卒じゃねーだろ"とマサカリがとんできたのでタイトル変えました。
サバを読んでてごめんなさい。今3年目です。
これからもよろしくおねがいします。
新卒ではないですがいつまでも若手です。
アプリケーション内でhttpsによる外部APIを叩いているサーバのメモリ使用量が増加し続ける件について
問題
アプリケーション内でhttpsによる外部APIを叩いているサーバのメモリ使用量が増加し続ける件について調べた。
該当のサーバでは、以下のようにメモリの使用率が徐々に上昇していく。
また、アプリケーションのプロセス自体がメモリを消費しているわけではない状態。
原因
調査すると、このバグ仕様を踏んでいるのではないかと思われるページを見つけた。
https://bugzilla.redhat.com/show_bug.cgi?id=1044666
内容としては、curlを実行した際に
/etc/pki/nssdb/以下の存在しないファイル(毎回違うパス)に対してaccessシステムコールが大量にコールされ、
negative dentry cacheが溜まっていき、メモリ使用量が圧迫されるというもの。
実際、この状況が起きているサーバを調べるとメモリ使用率のうち多くを占めているのはnegative dentry cacheであることがわかる。
$ free -k total used free shared buffers cached Mem: 3849124 1848376 2000748 0 145780 202468 -/+ buffers/cache: 1500128 2348996 Swap: 0 0 0
$ cat /proc/meminfo | grep Slab Slab: 1370992 kB
$ sar -v 13時22分26秒 dentunusd file-nr inode-nr pty-nr 13時22分27秒 6652734 832 13046 33
curl実行時に大量のaccessがコールされている状況も再現できた。
$ strace -fc -e trace=access curl 'https://www.google.com' > /dev/null % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 131 262 131 262 0 0 1812 0 --:--:-- --:--:-- --:--:-- 18714 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000211 0 646 640 access ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000211 646 640 total
このようなphpファイルを実行しても再現する。
https://gist.github.com/s-tajima/854936acc9526cd812b2
$ strace -fc -e trace=access php test.php % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000238 2 142 131 access ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000238 142 131 total
なぜこんなことになるのかというと、
https://hg.mozilla.org/projects/nss/file/4d876e0ee318/security/nss/lib/softoken/sdb.c#l372
ファイルシステムの性能を検査して、キャッシュを使うかどうかの判断をしているらしい。
対応
対応としては、
https://bugzilla.redhat.com/show_bug.cgi?id=1044666#c8
このパッチで使えるようになった、NSS_SDB_USE_CACHEのオプションを有効にして、
ファイルシステムの検査をせずにキャッシュを使うようにすればいいようだ。
$ sudo yum update nss-3.16.2.3-3.el6_6.x86_64.rpm nspr-4.10.6-1.el6_5.x86_64.rpm nss-util-3.16.2.3-2.el6_6.x86_64.rpm nss-softokn-3.14.3-22.el6_6.x86_64.rpm nss-softokn-freebl-3.14.3-22.el6_6.x86_64.rpm nss-sysinit-3.16.2.3-3.el6_6.x86_64.rpm
$ export NSS_SDB_USE_CACHE=yes ※phpのコード内でputenv("NSS_SDB_USE_CACHE=yes”)でもよい。 $ strace -fc -e trace=access php test.php % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- -nan 0.000000 0 12 7 access ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 12 7 total
改善された。
本番稼働環境におけるDRBDのDISKのresizeが遅い問題について
現在運用しているMySQLサーバはDRBDによってDISKの冗長構成をとっている。
また、DRBDのデバイスはLVMのLV上に構築しているので、
LVのサイズを拡張すればDRBDのリサイズ(drbdadm resize)で容量の拡張ができるようになっている。
今回の問題は本番稼働しているクラスタでDRBDデバイスのリサイズをした時に、
完了までに異様に時間がかかってしまう状態になってしまうことがあったことについて。
- 対象の環境
OS: Scientific Linux release 6.4 (Carbon) DRBD: 8.4.4
具体的には
# cat /proc/drbd .. snip .. speed: XXX (XXX) K/sec
の数字が250K/sec前後(開発環境では20,000K/secほど出る)となっている状態。
いろいろ調べてみると、DRBD8.4からデフォルトで有効になった、
sync rate controllerがキャップをかけている状態の模様。
http://blogs.linbit.com/p/128/drbd-sync-rate-controller/
DRBDでは通常の同期(normal replication)と再同期(resynchronization)は区別されていて、
今回のresizeは再同期として扱われる。
この機能は再同期が通常の同期の邪魔をしないように
再同期のスピードに制限をかけているらしい。
開発環境では通常の同期がそれほどの負荷になっていないため、このキャップがかかっていなかったと思われる。
以下のコマンドで一時的にキャップされる値の設定を変更して対応。
設定する値は要調整。この数字だと2,000K/secくらいにはなった。
# drbdadm disk-options --c-min-rate=1M <resource> # drbdadm disk-options --c-fill-target=200k <resource>
注意する点としてはc-min-rateの設定は''Secondary側(同期される側)''で変更しないと効かない模様。
https://cybozu.atlassian.net/wiki/pages/viewpage.action?pageId=5701634
尚、デフォルトの値はここに記載されている。
http://drbd.linbit.com/users-guide-8.4/s-recent-changes-defaults.html
設定がうまくいっているかは以下のコマンドで確認
# drbdsetup <resource> show
リサイズ完了後元の設定(設定ファイル通りの設定)に戻すのはこのコマンド
# drbdadm adjust <resource>