アプリのログを整形して運用を効率化する話

2021年12月5日公開

これはドリコム Advent Calendar 2021 の5日目です。
4日目は尾﨑春菜さんによる「今まさにこの瞬間からPhotoshopスクリプト始めたい人向けまとめ」です。

はじめに

こんにちは。入社4年目のエンジニアの渡邉です。普段は主にUnityを使いつつ、近頃はコードを書く以外の業務が多くなってきました。

私は運用中のプロダクトに所属していますが、チーム内では開発中も様々なトラブルが起きます。特にエンジニアには「なぜか動かないので調査してほしい」といった依頼が度々届きます。本稿ではそういったトラブルでエンジニアの手を少しでも止めないように、アプリから出力できるログをわかりやすい形にまとめてチャットに送信し活用している話をさせていただこうと思います。

また後半では具体的な改善手法の一つとして、レーベンシュタイン距離(編集距離)について解説し、それを利用した効率化事例についてご紹介します。

本稿の構成

今回は私の所属するプロダクトにおける運用事例を、以下の3段階に分けてお話していきます。

エンジニアによる調査コストを削減する
- ログを整形し必要な情報を読み取れるようにする
エンジニアとチームメンバーのコミュニケーションコストを削減する
- ログ送信時の状況も出力し調査の手間を削減する
エンジニアが調査しなくても良くする
- レーベンシュタイン距離でアセットダウンロードエラーを読み解く

今回開発環境にはUnityを使用していますが、それ以外でも応用できる話かと思います。あくまで私のチームにおける運用改善の事例になりますが、何かのお役に立てば幸いです。

背景

まずログの送信についてですが、アプリ内のデバッグメニューからUnityで出力されたログ等を送信する機能を指します。「adb logcat」で出すようなログとはちょっと違います。ログの取得には Application.logMessageReceived を使用します。ここの具体的な実装やチャットツールとの連携については本稿では述べません。

私が現在のチームに入った時からこのようなログを送信する機能自体はありました。ただそこまで有効に活用されている気配はなく、時々不具合発生時に送信されてエンジニアに調査依頼が飛んでくるようなものでした。内容が多過ぎて非常に読み取りづらいだけでなく、ログを表示しようとするとチャットが固まるような有様でした。

1. エンジニアによる調査コストを削減する

最初に、ログ送信の機能を快適に使用するための環境づくりを行います。

問題

当初、ログの中身は以下のようになっていました。
※あくまでイメージです。実際に出力したログではありません。


<size=12><color=#00FFFFff>31</color></size> : <size=12><color=#FF0000ff>例外</color></size> : KeyNotFoundException: The given key was not present in the dictionary.
System.Collections.Generic.Dictionary`2[System.String,System.String].get_Item (System.String key) (at Dictionary.cs:150)
ResourceManager:GetAsset(String)
AssetLoader:Load()

<size=12><color=#00FFFFff>30</color></size> : <size=12><color=#FF0000ff>例外</color></size> : KeyNotFoundException: The given key was not present in the dictionary.
System.Collections.Generic.Dictionary`2[System.String,System.String].get_Item (System.String key) (at Dictionary.cs:150)
ResourceManager:GetAsset(String)
AssetLoader:Load()

<size=12><color=#00FFFFff>29</color></size> : <size=12><color=#FF0000ff>例外</color></size> : KeyNotFoundException: The given key was not present in the dictionary.
System.Collections.Generic.Dictionary`2[System.String,System.String].get_Item (System.String key) (at Dictionary.cs:150)
ResourceManager:GetAsset(String)
AssetLoader:Load()

<size=12><color=#00FFFFff>28</color></size> : <size=12><color=#FFFF00ff>警告</color></size> Loading Failed
UnityEngine.Logger:Log(LogType, Object)
AssetLoader:Error()
AssetLoader:Completed()

<size=12><color=#00FFFFff>27</color></size> : <size=12><color=#FF0000ff>エラー</color></size> : Resource Manager: Resource Download Error 2d/image/211206.dat
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
Utils.LogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, String, Object)
Utils.Debug:Log(LogType, String, Object)
ResourceManager:GetAsset(String)
AssetLoader:Load()
Battle:LoadImage()
Battle:Initialize()
Scene:StartScene()

<size=12><color=#FFFFFFff>26</color></size> : <size=12><color=#FFFF00ff>ログ</color></size> 211206が入力されました
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
Utils.LogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, String, Object)
Utils.Debug:Log(LogType, String, Object)
ResourceManager:GetAsset(String)
AssetLoader:Load()

これでは読む気が起きませんね。文字装飾のためのタグが表示されていたりスタックトレースが長かったりと、不要な情報が多く含まれていました。このため、「エラーが起きている時のログがどこか」を見つける作業から始まり、最悪の場合は不要なログのせいで必要なログが消えてしまっていることもありました。

ログを整形し必要な情報を読み取れるようにする

ログ内容を以下のように修正することでシンプルにし、ログ全体の文字数を減らしました。

タグは使用しないようにした
- 色分けはタグを使わず文字色そのものを変えることで代替しました
通常のログ（LogType.Log）はスタックトレースを表示しない
- スタックトレース無しで把握できるよう出力内容も調整しました
それ以外のログのスタックトレースは4行だけ表示にする
- 5行以上になるとほぼ自明なメソッドばかりになってしまうため、3,4行程度あれば十分でした
- また最初の行はログに関するもの(ILogger)のため非表示にしました
直前のログと全く同じログは追加表示しないようにする
- この場合は重複数を付け加える形にし、同じエラーで埋め尽くされることを防ぎました

これらの結果、ログは以下のようになりました。前述のログと内容は同じですが、必要な情報がわかりやすくなりました。


【29】例外　重複数:3
KeyNotFoundException: The given key was not present in the dictionary.
System.Collections.Generic.Dictionary`2[System.String,System.String].get_Item (System.String key) (at Dictionary.cs:150)
ResourceManager:GetAsset(String)
AssetLoader:Load()

【28】警告
Loading Failed
AssetLoader:Error()
AssetLoader:Completed()

【27】エラー
Resource Manager: Resource Download Error 2d/image/211206.dat
ResourceManager:GetAsset(String)
AssetLoader:Load()
Battle:LoadImage()
Battle:Initialize()

【26】通常
211206が入力されました

結果

ログが送信されるチャット部屋を開くと固まるといったことも起きなくなり、ログ送信機能が積極的に活用されるようになりました。また表示内容を減らしてはいますが、必要な情報が失われたということもなく利用できています。

2. エンジニアとチームメンバーのコミュニケーションコストを削減する

次に、実際にログを活用する際の問題点に着目します。

問題

普段ログ送信機能を利用するのは、主にエンジニア以外のチームメンバーです。メンバーが開発環境にて期待通りにアプリを動作させられていない場合に、ログを送信しエンジニア調査依頼を投げることが多いです。ここでエンジニアが調査をするのですが、この時内容によっては調査のために以下の情報が必要になることがあります。

使用しているユーザーデータのID
使用している端末
使用しているアプリ
接続先サーバー
アプリ内の時刻
ログ送信時のシーン

慣れているチームメンバーの場合は調査依頼時にこれらの情報を送ってくれることもあるのですが、多くの場合はログしか送信してもらえないので、エンジニアからヒアリングを行っていました。これによりヒアリングの手間がかかるだけでなく、内容によっては再度不具合を再現させて状況確認するといった作業が発生しておりました。

ログ送信時の状況も出力し調査の手間を削減する

この問題は単純で、送信されるログにそのままアプリの情報を載せてあげることで解消しました。使用している端末・アプリの情報はUnityの場合、以下で取得できます。

UnityEngine.Application.productName
UnityEngine.Application.version
UnityEngine.SystemInfo.operatingSystem
UnityEngine.SystemInfo.deviceModel
UnityEngine.iOS.Device.generation

ユーザーデータ、接続先サーバーは各アプリ内の実装によるため省略します。
アプリ内時刻は、サーバー上のチートにより時間移動ができる場合は欲しいです。出力は以下のように、時刻表示だけではなくタイムゾーンも出力しておくと良いでしょう。過去にはタイムゾーンが異なることによる不具合も発生したことがあります。

System.DateTime.ToString("yyyy/MM/dd HH:mm:ss zzz");

ログ送信時のシーンについては、シーン遷移履歴を直近4シーン分保存しておき、ログ出力時に参照します。これらを導入したイメージとしては以下のようになります。

【ユーザーID】34769840
【使用端末】iOS 14.8 iPhone9,1(iPhone7)
【使用アプリ】 (2.0.0)
【接続サーバー】Develop
【シーン履歴】：<Battle> ← <Home> ← <Login> ← <Title>
【アプリ内時刻】：2021/12/06 15:34:00 09:00

ログ送信時の状況が自動的に付与されるようになったことで、調査が非常に楽になりました。よくあるトラブルとしては「使用しているアプリが古い」「使用しているアプリと接続すべきサーバーが一致していない」といったことがありました。これらは調査してもわからないことが多いのですが、ログで確認できることでパッと目に付くようになりスムーズに解決するようになりました。

3. エンジニアが調査しなくても良くする

前項までの内容を入れたことで、以前よりもずっと効率的にログが活用されるようになりました。ただ結局のところエンジニアの調査が必要である点は変わりません。そこで、エンジニアの手を動かさなくてもチームメンバーが自身で解決できるようなログの出力を考えます。さすがに全ての問題を解決することはできないので、本稿ではアセットのダウンロードに関する1つの問題に絞って改善事例をご紹介します。

問題

チームの企画メンバーが運用の施策のデータを作成し、実機で確認する際のお話です。運用施策は基本的に新規実装は絡まないので、エンジニアは関わりません。それ以外のメンバーだけで作成できるような仕組みとなっています。

このような場面として使用する画像等のアセットバンドルをダウンロードするために、各施策のマスタデータ上で使用する画像の名前を指定することがあります。ここで時々画像が読み込めず調査してほしいといった依頼が来ます。読み込めない理由としては以下のようなものがあり、意外と複雑です。

画像名の指定が間違っている
画像にアセットバンドル名が正しく設定されていない
画像が開発環境に投入された直後でまだ配信されていない
開発中の新機能による不具合が起きている
その他、特殊な条件下で発生する既存の不具合が起きている

これらの5つのうち、大抵の場合は上の3つのどれかなので、エンジニアが関わらない内容です。これらはそれぞれ見るべき箇所が異なっているため、調査にも手間がかかります。

レーベンシュタイン距離によりアセットダウンロードエラーを読み解く

複数の原因が考えられるこの問題を解消するため、正しく読み込めなかった画像名に対して正しい名前を提案するような機能を考えます。この機能があれば原因の切り分けができるだけでなく、画像名の指定ミス時はデータ設定者が直接正しい設定を確認することができます。これにより多くのエラーがエンジニア無しで解決できるようになるほか、調査の手助けにもなります。ではこの機能を実現させる方法を考えていきます。

大まかな仕組み

アプリ内ではリソースリストと呼ばれる、使用する全てのアセットバンドルの名前とダウンロードに必要な情報が含まれたファイルが存在します。そのため入力された画像名に対して、リソースリスト内から最も類似している画像名を算出してあげればよいのです。この類似している名前を算出する方法ですが、ここではレーベンシュタイン距離というものを考えます。

レーベンシュタイン距離

レーベンシュタイン距離とは、2つの文字列がどれぐらい類似しているかを一方の文字列からもう一方の文字列に何ステップで変換できるかを表したものです。編集距離とも呼ばれます。ここでの1ステップは、以下の「挿入」「削除」「置換」の各操作を指します。

挿入
- 1文字追加することです。例えば「明日」から「明後日」へは挿入1回で変換できます。
削除
- 1文字削除することです。挿入の逆の操作になります。
置換
- 1文字を別の文字に置き換えることです。例えば「明日」から「昨日」へは置換1回で変換できます。

「ドリコム」から「ドラム」へは2ステップで変換できるため、距離は2となります。

アルゴリズム

レーベンシュタイン距離の実装にあたり、まずは考え方をまとめます。調べればもっと丁寧に述べられているページはたくさんあると思いますが、本稿でも一通りご紹介します。興味ない方、知っている方は後述の「アセットの名前を出力する」の項目まで飛ばしてお読みください。

レーベンシュタイン距離は動的計画法という方法で求めることができます。動的計画法とは、小さい問題の答えを使ってより大きな問題を再帰的に解くような方法です。イメージとしては例えば「ドリコム」から「ドラム」を変換する際、直接的に考えるのは難しいですが「ドリム」、「ドラコム」という中間の文字列からは1ステップで「ドラム」に変換することができます。つまり「ドリコム」から「ドリム」、「ドラコム」への最短の距離がわかれば、それらの距離に1ステップ分を足したもののうち最も小さいものが「ドリコム」から「ドラム」への距離であると言うことができます（あくまでイメージです）。

上記の例では目標の状態から考えていますが、
実際には1文字目から順番に算出し、徐々に大きな文字列の距離を算出していきます。そして元の文字列のx文字目までと、目標の文字列のy文字目までの距離を2次元配列[x, y]で保存します。この配列の値の求め方を以下で詳しく見ていきます。

STEP1. [x, 0] の初期化
x文字の文字列を全て削除するだけなので [x, 0] = x を代入します。xの最大値は変換前の文字数である4です。

STEP2. [0, y] の初期化
空の文字列から y文字分を追加するだけなので [0, y] = y を代入します。yの最大値は変換前の文字数である3です。

STEP3. [1, 1]を考える
本当はここからSTEP4.と同様に3種類の距離を考えますが、ここでは省略します。明らかに同じ文字なので距離は0になります。

STEP4. STEP3.の隣の値[1, 2]を考える
以下の3種類の距離を考えます。

①
[0, 2]の距離に、変換前の文字列を1文字追加する(空文字列を”ド”に)ステップを追加した [0, 2] + 1

②
[1, 1]の距離に、変換後の文字列を1文字削除する(“ドラ”を”ド”に)ステップを追加した [1, 1] + 1

③
[0, 1]について、同じ文字を変換前後双方の末尾に追加する。同じ操作であれば、行う前と距離は変わらない。各文字列の末尾（”ド”と”ラ”）が一致していれば [0, 1] がそのまま③の距離となるが、今回は一致していないのでそこからさらに変換後の文字列を1文字置換するステップを追加する。よって [0, 1] + 1

以上の距離は、それぞれ事前に格納している値から算出でき、①は距離3、②は距離1、③は距離2となります。ここで①～③のうち、最も値が小さいものを[1, 2]の最短距離として扱います。よって②が採用され[1, 2] = 距離1となります。

一見複雑ですが、①と②では隣のマスの状態から1回挿入・削除の操作を行うだけなので距離は1増えます。③は斜め上のマスから同じ文字を追加しているなら同距離、そうでなければ置換の操作が必要なので距離が1増えるという違いです。

STEP5. STEP4.を繰り返す
配列[x, y]のうち、隣り合う[x-1, y]と[x, y-1]の2箇所が求まっているところはSTEP4.より計算可能です。

STEP6. 一番最後の値[4, 3]を見る
STEP5.が完了すると2次元配列が全て埋まった状態となります。
この時、一番末尾にあたる[4, 3] = 2は要するに【”ドリコム”→”ドラム”の変換の距離】という意味となり、求めたい距離となります。

実装

上述のアルゴリズムに沿って実装すると以下のようになります。説明内の各STEPと同じ順番になっていない箇所がありますが、全体の処理は同じです。


public int LevenshteinDistance(string s1, string s2)
{
    int length1 = s1.Length;
    int length2 = s2.Length;

    if(length1 == 0) return length2;
    if(length2 == 0) return length1;

    char[] c1 = s1.ToCharArray();
    char[] c2 = s2.ToCharArray();

    int[,] distance = new int[length1 + 1, length2 + 1];

    for(int index1 = 0; index1 < length1; ++index1)
    {
        distance[index1 + 1, 0] = index1 + 1;
        for(int index2 = 0; index2 < length2; ++index2)
        {
            distance[0, index2 + 1] = index2 + 1;

            int cost = c1[index1] == c2[index2] ? 0 : 1;

            distance[index1 + 1, index2 + 1] = Mathf.Min(
                distance[index1 + 1, index2] + 1,
                distance[index1, index2 + 1] + 1,
                distance[index1, index2] + cost);
        }
    }

    return distance[length1, length2];
}

アセットの名前を出力する

では実際にレーベンシュタイン距離を使用し、間違っているアセット名とそれに類似するアセット名をログ出力するようにします。実装としては単純で、間違っているアセット名とリソースリストに存在する全てのアセット名とのレーベンシュタイン距離を算出していきます。全てを出力すると大変なことになるので、「距離が近いものから10件」「距離10以内」のアセット名のみを出力していきます。重そうな処理ではありますが、エラー時しか動作させないためパフォーマンスは気にしません。低スペックな端末上でもすぐ出力されます。出力内容は以下のようなものになります。この例では、「211206」というIDのリソースを指定する予定が、誤って「201206」を指定してしまった想定です。

2d/image/201206.dat　入力

2d/image/211206.dat　距離:1
2d/image/201208.dat　距離:1
2d/image/211106.dat　距離:2
2d/image/211203.dat　距離:2

このような表示が出てくることで、エンジニア以外のメンバーでもIDが間違っていると気づくことができます。また「画像にアセットバンドル名が正しく設定されていない」「画像が開発環境に投入された直後でまだ配信されていない」といったトラブルが起きている場合、以下のようなログ出力になります。

2d/image/211206.dat　入力

2d/image/211106.dat　距離:1
2d/image/211203.dat　距離:1
2d/image/201208.dat　距離:2

このように正しい名前を入力しているにも関わらず候補に挙がってこない場合、
名前指定の問題はなく、配信がされていないところに問題があるとわかります。

結果

発想自体は単純な機能ですが非常に効果があり、チーム内でも好評いただいています。エンジニアの調査の手間が減ったことはもちろんですが、非エンジニア(主にデータ入力者)が自己解決できるようになったことで手が止まってしまう時間が削減されました。原因がわかりづらいエラーだと1回10分以上悩んだりすることもありましたが、現在ではそういうことも無くなりました。わかりづらいものの例として過去には、画像名の末尾に不要な半角スペースが入っていたこともありましたが、本機能導入後は正しく検知され一瞬で解決しました。

これらにより、エンジニアだけでなくチーム全体として一連の作業がとても効率化されました。

まとめ

本稿では、実機で出力されるUnityのログを有効活用した運用効率化について3項目に分けてご紹介しました。いずれも大したことはやっていないのですが、意識しないと案外そのまま放置されてしまうようなところかもしれません。私のチームでは比較的少人数で運用していることもあり、できる限り無駄な作業は減らしていく必要があります。

3年前のアドベントカレンダーでも述べましたが、こういった運用業務にたくさん手を取られてしまうと、アプリを遊んでいただいているユーザーに直接届くものを生み出すといった、エンジニアとして真にやるべきであると考えていることに時間を割けなくなってしまいます。なので積極的に改善していきたいですね。

今回ご紹介した事例はほんの一部ですが、皆さんの周りでももしかすると何か改善できることがあるかもしれません。特に自分の作業だけでなく、他のエンジニアやそれ以外のチームメンバーに目を向けることで新たな発見があったりもします。

6日目はむらおさんです。

ドリコムでは一緒に働くメンバーを募集しています！
募集一覧はコチラを御覧ください！