ストレージ診断ログのblobアクセスログを解析する

あー、ついに禁断の地へｗ

パブリッククラウド全般に言える共通点ですが、データが外からクラウドへ

入ってくる分には無料だけど、クラウド内の同一リージョンもしくは同一

データセンターから外に行く分（主にダウンロードやリスト表示等）には

課金される、という法則は一般的ですね。

※ベンダーから見ると簡単に無料でデータが他社に引っ越されてしまうのは

　いかんぜよ、という昔からの戦略というか怖い意志がありますからねｗ

もちろんAzureでも同様なのですが、よくある話としては以下のような

ケースです。EAポータル等から課金レポート(csv)をダウンロードして

見たり、Azure Cost Managementを使ってリソースタグの集計結果グラフ

などを見ていると、ある日を境に突然blobのデータ転送料がドエライこと

になっててビビる！というものです。特にこれは複数の部門やチームに

跨ってAzureをご利用頂いている時に起きますかね。

そしてエンタープライズオーナーやサブスクリプションオーナーが

ぎゃあぁ！なんだこれ！今月分くっそ高いぞ！てか誰だよこんな使い方

してるやつはぁ！っと目くじら立て原因の特定に入っていきます。

さて、ぼちぼち本題にはいっていきますが、もちろんストレージ

アカウントのストレージ診断をONにしていないと細かい原因がわかり

ません。以下Azure Portalの設定個所です。オンにしておきましょう。

ストレージ診断をONにしておくと、このストレージアカウント

に自動的に$logs というコンテナが作成されます。先頭が$で始

まっているので、隠しディレクトリという扱いのようです。

この $logs 配下の階層は、/YYYY/MM/DD/HHmm/000000.log の

ようになっていますが、アクセスがないと何も作成されません。

※mmの部分は固定で00になるので「分」までは厳密なディレ

クトリ管理はしていません。

※000000.log は時間をおいてアクセスすると000001.log のように

　インクリメントされたファイル名として複数に分けられます。

この000000.logファイルのフォーマットは以下に記載があります。

https://docs.microsoft.com/ja-jp/rest/api/storageservices/storage-analytics-log-format

つまりこの000000.logのテキストファイル（アクセスログ）を

解析すれば何か原因がつかめそうですが、いかんせん、とても、

や、、ややこしいｗ

ということでLinuxな人ならではの解析方法をいくつか紹介しておきます。

とりあえずblobfuseでblob/$logsをマウントし、コマンドが実行できる

状態にしましょう。

以下を参考にマウントします。（rpmでパッケージをダウンロードする

際のOSのバージョンに注意してください）

https://docs.microsoft.com/ja-jp/azure/storage/blobs/storage-how-to-mount-container-linux

※注意

　CentOS7でこの手順を行うと yum install -y blobfuse を実行した時に

　以下のエラーが出る場合があります。

　---> Package fuse-libs.x86_64 0:2.9.2-11.el7 will be installed
--> Finished Dependency Resolution
Error: Package: blobfuse-1.0.2-1.x86_64 (packages-microsoft-com-prod)
           Requires: libgnutls.so.26(GNUTLS_1_4)(64bit)
Error: Package: blobfuse-1.0.2-1.x86_64 (packages-microsoft-com-prod)
           Requires: libgnutls.so.26(GNUTLS_2_10)(64bit)
Error: Package: blobfuse-1.0.2-1.x86_64 (packages-microsoft-com-prod)
           Requires: libgnutls.so.26()(64bit)
 You could try using --skip-broken to work around the problem
 You could try running: rpm -Va --nofiles --nodigest

　この場合は libgnutls.so.26 という共有オブジェクトがねぇ！って

　言われてますが、yumのキャッシュが邪魔している時があるので

　yum upgradeした後なんかは以下の手順でクリアにするとblobfuseが

　インストールできます。

# yum remove packages-microsoft-prod-1.0-1.el7.noarch
# yum clean all
# rm -rf /var/cache/yum
# rpm -Uvh https://packages.microsoft.com/config/rhel/7/packages-microsoft-prod.rpm
# yum install blobfuse fuse -y

　あとストレージアカウントの設定ファイルとして用意する

　fuse_connection.cfg のコンテナ名は、普通に $logs と入れます。

　こんな感じで。（ストレージアカウントのキーはマスクしてます）

無事 $logs をマウントできれば

以下のように操作できる状態になっていると思います。

ここまでで取り合えず解析する準備ができました。いよいよ本ちゃんです。

なにやらデリミタ（区切り文字）は「;」セミコロンになっているようです。

●blobへのアクセスが集中している時間帯を特定しよう

# cd /${mount_point}/${blobdir}/blob/YYYY/MM

# awk -F";" '{ print $2 }' ./*/*/*.log | cut -f1 -d":" | sort | uniq -c | sort -nr

　出力結果サンプル

　 167 2020-04-29T21
     42 2020-04-29T23
     1 2020-04-29T03

　⇒　4/29の21時が1番アクセスが多い時間だとわかります。

　　　4/29の21時はUTCです。+9時間のJSTに読み替えましょう。

　　　あと診断ログの日付フォーマットはISO8601になってます。

　　　わかりやすい日付フォーマットにする場合は、pythonや

　　　phpでやったほうが楽かと。

●4/29 21時のログから何のリクエストが多いのかを特定しよう

# cd /${mount_point}/${blobdir}/blob/YYYY/MM/DD/2100

# awk -F";" '{ print $3,$4 }' ./*.log | sort | uniq -c | sort -nr

　出力結果サンプル

     89 ListBlobs Success
     46 GetBlobProperties BlobNotFound
     14 GetBlobProperties Success
      6 BlobPreflightRequest AnonymousSuccess
      3 GetBlob Success
      2 ListBlobs SASSuccess
      2 GetBlobProperties SASSuccess
      1 ListContainers Success
      1 ListBlobs OAuthAuthorizationError
      1 GetContainerServiceMetadata Success
      1 GetContainerProperties Success
      1 GetBlobServiceProperties OAuthAuthorizationError

　⇒　ListBlobsの成功(Success)が 89 回あったことがわかります。

●どのURL(blob object)へのアクセスが多いかを特定しよう

# awk -F"\"|&" '{ print $2 }' ./*.log | sort | uniq -c | sort -nr

　出力サンプル

    170 https://share001.blob.core.windows.net:443/$logs?comp=list
     13 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2100/000002.log
      9 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2100/000003.log
      9 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2100/000001.log
      9 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2100/000000.log
      8 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2100/.hoge.swp
      6 https://share001.blob.core.windows.net:443/url?restype=container
      6 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/30
      4 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2300/000001.log
      4 https://share001.blob.core.windows.net:443/$logs/blob/2020/04/29/2300/000000.log

　⇒　$logs のリスト表示が多いのがわかるが、今操作しているblobfuseの

　　　ログも出力されるので、grep -v "\$logs" を追加すると良いかも。

　　　あとURL抽出だとクエリ内で使われる「&」が大量に出るため

　　　awkのデリミタには「＆」も追加して検索。

●どこのソースIPからのアクセスが多いかを特定しよう

# awk 'BEGIN {FS="\"";OFS="\""};{gsub(";", "",$2);print}' ./*.log | awk -F";" '{ print $16 }' | cut -f1 -d":" | sort | uniq -c | sort -nr

　出力サンプル

  266 172.19.0.4
    12 106.73.2.64
      3 10.81.128.71

　⇒　172.19.0.4 からのアクセスが266回と1番多いことがわかる。

　　　いきなりawk文がややこしくなったが、デリミタとしていた「;」

　　　がダブルクォート内のURLにも利用されるためこのようにした。

●特定の時間にGetBlobされたデータ容量の合計を出そう

# grep "2020-04-30T00:" *.log | grep ";GetBlob;" | awk 'BEGIN {FS="\"";OFS="\""};{gsub(";", "",$2);print}' | awk -F";" '{ sum += $21 } END { print sum }'

　出力サンプル

345161

　⇒　2020年4月30日の09時(JST)に、約345kbyteのデータ量が

　　　GetBlobのリクエストで取得された総データ量。

●おまけ：利用しているblobのAPIバージョンを全て特定する

 # awk 'BEGIN {FS="\"";OFS="\""};{gsub(";", "",$2);print}' ./*.log | awk -F";" '{ print $17 }' | sort | uniq -c | sort -nr

 　出力サンプル

  266 2017-04-17
      6 2019-10-10
      6 2015-02-21
      3 2019-07-07

 　⇒　2017-04-17のAPIバージョンが1番利用されていることがわかる。

とまぁsedでやると正規表現コテコテになるのでawkでやってみたけど

awkでも結構難解になりましたね（汗

もちろん診断ログはLog Analyticsへ飛ばすこともできるので

お金かけてkustoで検索した方が楽だと言う方はそっちをお薦めします。

今回はこんなところで。