Swiftにおけるロギング

Swiftにおけるロギング

Swiftの統合ロギングAPIの最新バージョンをご確認いただけます。Appでプライバシーの保護を実現し、イベントやエラーのログを取る方法を学びましょう。パーフォーマンスを落とすことなく、データフォーマット用のパワフル、かつ読みやすいオプションをご利用いただけます。また、App内の予期せぬ動作を認識しデバッグするのに役立つ、ログメッセージの収集および処理方法についてお伝えします。

リソース
- - HDビデオ
  - SDビデオ
関連ビデオ

WWDC23
- 構造化ロギングによるデバッグ
WWDC20
- Swiftの新機能
ダウンロード

こんにちは　WWDCへようこそ “Swiftでロギングしてみる” 私はAppleのエンジニアラヴィ･カンダダイ･マダヴァンです今回はos_logとも呼ばれる Appleの統合ロギング APIを使って― アプリケーションのデバッグをより簡単にする方法を紹介しますアクセス権を持つデバイスからログを収集する方法を説明しアプリケーションの問題を把握して修正するのに有効なツールのデモを行います
ログ呼び出しのパフォーマンスの管理方法とフォーマッティングオプションでログメッセージのリーダビリティを向上させる方法も紹介しますバグを修正することは大切です信頼できバグがほとんど生じない高品質のアプリケーションをユーザは期待しています小さくともバグが存在するとユーザ体験が低下しかねません他に比べて修正が困難なバグもありますなかなか見つけられないバグは大抵開発中に再現が難しいバグです再現しにくいバグを検出し修正するのにログは有用なツールですバグを再現することなくバグを把握するための手がかりを提供します私が開発しているアプリケーションの再現しにくいバグを見てみましょうその後このバグを把握･修正できるようにロギングを追加する方法を説明します
Frutaというアプリケーションを使えばユーザはスムージーを購入できますスムージーを閲覧しスムージーをタップすればそれを購入できます
最近私はこのアプリケーションに “ギフトカード”機能を追加し― ギフトカードを閲覧するためのタブを作成しました Apple Payを使用して購入するにはカードをタップしますスクロールして最後のカードに到達するとアプリケーション内ではサーバーと通信し追加のカードの読み込みが始まりますカードをタップして１枚選ぶとアプリケーション内のカードの読み込みや通信が停止しますしかし　戻って引き続き追加のカードを閲覧することもできます大抵このように機能しますが残念ながら時折バグが見られることもありますアプリケーションがカードを読み込んでいる時にカードをタップするとエラーで読み込みが失敗することもあります
このエラーは私の開発機の近くで生じないのでもどかしいです
非常にまれにしか生じないエラーなのでデバッガーで再現できませんアプリケーションにロギングを追加すればこのようなエラーを再現せずとも把握できます Xcode 12では統合ログに使用する新しいSwift APIを導入していますアプリケーション実行時に発生する重要なイベントをこれらのAPIで記録できますログはオペレーティングシステムによりアーカイブされるため後でデバイスから取得できますこれらの新しいAPIは非常に効率的なのでアプリケーションの動作遅延を招くことなく広範囲で使えます
たった３つの簡単なステップでアプリケーションにロギングを追加できますまず新しいロギングAPIを定義する “OS”モジュールをインポートします次に Logger型のインスタンスを作成しサブシステムとカテゴリを渡しますこれらはLoggerで記録される各メッセージに添付されますサブシステムは通常アプリケーションから送られたメッセージを識別できるバンドル識別子ですこのカテゴリを使えばプログラムの各部分から送信されるメッセージを詳細に区別できますここではLoggerの“ギフトカード”カテゴリを使っています
最後にLoggerインスタンスのメソッドを呼び出しコード内の適切な場所にロギングを追加しますデータがサーバーからアプリケーションにダウンロードされるたびにログを追加しています
Loggerで文字列補間を使えば実行時間データをログメッセージに追加できます例えばここでログメッセージにタスク識別子を追加していきますこれは印刷関数を呼び出すのと似ています
ただしログメッセージには重要な相違点があります印刷と違いログメッセージはよく遅延するため完全には文字列に変換されませんそのかわりにコンパイラとロギングライブラリが連携しロギングデータの型を利用するログメッセージを大幅に最適化して表示させます表示が最適化された場合はログメッセージが実際に表示される場合にのみ文字列に変換する代償を払う必要がありますログメッセージにはさまざまなデータ型が含まれる可能性があります IntやDoubleなどの数値タイプや Objective Cオブジェクト― SwiftのCustomStringConvertibleプロトコルに準拠する型をロギングできますつまり独自の型をログメッセージに追加するには CustomStringConvertibleに準拠させるだけでいいのです実行時間データをログメッセージに追加する場合― 文字列やオブジェクトなどの数値以外の型が― ログで編集するように初期設定されている点に注意してくださいこれが行われるのはアプリケーションが出荷されユーザのデバイスで実行された時に― ログに個人情報が表示されないようにするためです
例えば文字列で表されるユーザの銀行口座番号が含まれているメッセージをロギングした場合― 出力ログでは口座番号は個人情報として編集されます
ただし機密情報を扱わないデータの場合はログで可視化できます実行時間データをロギングする場合は値“.public”を― オプションのパラメータ個人情報に渡します
これでログでデータの内容が表示されるようになりますここにスムージーの名前が１つありますプライバシーについての詳細はのちほど紹介します
アプリケーションでロギングされたメッセージはオペレーティングシステムにより圧縮された形式でデバイスに保存されます Macの“log collect”コマンドでこれらのログを取得できますまずデバイスをMacに接続します次にデバイスオプションを指定して端末から“log collect”コマンドを実行します
ログが必要なタイミングを開始時刻として指定します通常はバグを最初に確認した数分前を指定しますアーカイブログを格納するためのファイル名も指定しますアーカイブログをダブルクリックしてコンソールアプリケーションでアーカイブログを開きますこのアプリケーションを使えばログの閲覧やフィルタリングがしやすくなります Fruta アプリケーションで再現が困難なバグをロギングを使って把握する方法を見てみましょう “ギフトカード”ビューのソースコードにロギングを追加しました
私はOSモジュールをインポートしロギングAPIを開いてバンドル識別子と“ギフトカード”カテゴリを持つLoggerを作成しましたこのビューで実行されたイベントを記録するためロギング機能を追加しました例えばアプリケーションを使ってサーバーと通信するタスクを開始するとタスクを一意に識別するUUIDがロギングされるようになりました識別子には機密情報が含まれていないのでログで可視化するように公開しましたログ収集を使ってログアーカイブから Fruta アプリケーションのログを抽出しましたではこれをコンソールアプリケーションで開いてみますここにはたくさんのログエントリがありますシステム内の全プロセスを通じてロギングされたメッセージが含まれているからですアプリケーションの“検索”や “フィルター”機能で確認したいログを絞りますまずサブシステムでフィルタリングしますこの例ではアプリケーションのバンドル識別子ですそして Fruta アプリケーションからのメッセージのみを表示するように絞ります
右上の検索フィールドをクリックしサブシステムを入力します
そしてドロップダウンリストからサブシステムを選択します
アプリケーションのログのみをスクロールしてエラーに対応するメッセージを探します
私のアプリケーションでは多数ロギングしているのでエントリがまだたくさんありすぎて他の問題を把握しづらくなっています本当に必要なのは問題を絞り込む方法ですロギングされたタスク識別子のソリューションを利用します問題が生じたタスクのタスクIDで絞り込み問題に関連するログのみを表示しますタスク識別子を別のキーワードとして検索フィールドに追加し実行してみます
今存在しているログに目を通しエラーを把握します
最初のエントリは追加のギフトカードをフェッチするタスクがアプリケーションで開始していることを示しますそしてネットワークエラーのためにタスク完了となりタイムアウト後に再試行するため待機中であることが分かります次のエントリはその間に― タスクを停止しようとするギフトカードをユーザが選んだことを示していますしかしこの時点でアクティブなタスクがないためアプリケーション自体が矛盾した状態で検出され失敗しますこれで実際に生じた問題を再現できますカードを１枚選択することによってネットワークエラーにより停止したタイミングで追加のギフトカードを読み込むタスクを止めようとしましたこれでバグを再現しにくい理由が分かりましたイベントとネットワークエラーのタイミングに関係しているのですログのおかげでバグを把握し修正することができます
“log collect”でアプリケーション実行後にログを収集できることを確認しましたアプリケーション実行中にログをストリーミングすることもできますデバイスがMacに接続されている場合はコンソールアプリケーションで発生したログメッセージをストリーミングできますアプリケーションがXcodeで起動された場合は Xcodeのコンソールにも表示されますこれは“printf”のデバッグのかわりとして― 簡単に絞り込みができより構造化された出力ができるので便利です
コンソールアプリケーションでログを参照していた時に “failure”というメッセージが強調表示されていましたこれは私がエラーログレベルでロギングしたためですロギングAPIではメッセージの重要度を示す５つのログレベルがあります
重要度が低い方から順に並べると “デバッグ”“情報” 初期設定の“通知”“エラー” “障害”です
デバッグレベルは有用なメッセージに対してデバッグ時に限り使われます情報レベルはトラブルシューティングエラーに有用ではあるが不可欠ではないメッセージに使われます通知レベルはトラブルシューティングに不可欠なメッセージに使われますエラーレベルは実行中に発生するエラーを記録するために使われます障害レベルが最も深刻ですプログラム内の潜在的なバグが原因で発生する状況を記録するために使われますプログラムが保持するはずの前提が実行時に破られたことを記録するのにも使われますエラー･障害レベルはコンソールアプリケーション内で黄色と赤で表示されます
Loggerの型には各ログレベルのメソッドがあります例えばデバッグメッセージをロギングするには Loggerでデバッグ関数を呼び出しますログレベルを選ぶ際に考慮すべき重要事項は持続性ですつまりアプリケーションの実行が終了した時点でログメッセージをアーカイブしたり取得することが可能かどうかです持続性のないログの場合アプリケーションの実行中にしかストリーミングできませんメッセージに持続性があるか否かはログレベルで異なりますメソッドの重要度が高いほど持続性も高くなります
デバッグレベルのメッセージは持続性がありませんつまりアプリケーションの実行が完了した後に取得することはできないのです情報レベルのメッセージの大半は持続性がありませんがログ収集コマンドまでの短い時間に作成されたメッセージは例外です他の各レベルでロギングされたメッセージは継続性があり後で取得できますただしアーカイブするメッセージの数には容量制限があります制限を超過すると古いメッセージから削除され閲覧できなくなりますエラー･障害レベルのメッセージは通知レベルのメッセージより長く保持されます通常メッセージは数日間保持されますがデバイスの空き容量によって異なります
ログレベルもパフォーマンスに影響しますロギングでは一般的にオーバーヘッドが低くなりますがログレベルでは互いに相対的に異なるパフォーマンスが保持されます重要度が低いレベルほど速いのです障害レベルの場合は最も遅くデバッグレベルの場合は最も速いです
デバッグレベルでのロギングが高速な理由はデバッグメッセージが全く保持されないからですログがストリーミングされていない場合これらは破棄されますさらにSwiftコンパイラでは高度な最適化によりデバッグメッセージが破棄された場合メッセージ作成のコードが実行すらされませんつまりデバッグレベルでは詳細なメッセージをロギングしメッセージ作成のために負荷の高い関数を呼び出すことができますその代償をユーザが払うことはありません
タスク識別子などの実行時間データを含む Fruta アプリケーションを使い― ログ内のメッセージがデバッグにさらに有用になったことを説明しましたただし数値や文字列などの生データは把握や解釈が難しい場合があります実行時間を犠牲にせずにリーダビリティを向上させるデータのフォーマット方法をロギングAPIは多数提供しています Fruta アプリケーションに戻りログメッセージのフォーマッティングを活用してデバッグする方法を確認しましょうギフトカードビューでパフォーマンス上の問題が発生していますカードの読み込みに非常に時間がかかる場合がありますギフトカードの読み込みに複数のサーバーが使われていますどのサーバーが選択されているかがパフォーマンスの問題に関与しているのでしょうこれを調べるためにロギングを追加しサーバーとの通信に関する統計情報を収集します
タスクごとにタスク識別子フェッチされたギフトカードの識別子― 要求を処理したサーバータスク完了までの合計期間をロギングします
次にMacにiPhoneを接続し Xcodeからアプリケーションを実行し Xcodeのコンソールでログを表示します
残念ながらログが整列していないため非常に把握しづらい状況ですよってフォーマッティングオプションを使ってこの見た目を改善します
まずギフトカード識別子を固定幅にするためカード識別子で保持可能な最大文字数を表示します
今回は高い精度を必要としていないので小数点以下２桁の時間に丸めます
アプリケーションを再起動しログを再度表示してみます
これでログが読みやすくなりましたきちんと整列しているのでオプションキーを押したまま“列選択”を使用しフィールドをコピーします
これらをNumbersに貼り付けデータを可視化します
このグラフを見れば遅延タスクはすべてサーバー３で処理したことが明らかなのでメンテナンスのためにサーバーをオフラインに設定します
要するにデータフォーマットにオプションの “format”と“align”パラメータを使いますロギングAPIによるデータフォーマットではログ呼び出しの手間が省けるのでデータを最大限見やすく把握しやすくするのにフォーマッティングを好きに使えますロギングAPIの数多くのフォーマッティングオプションのうち一部を説明したにすぎません
Xcodeのコード補完を使ってあらゆるオプションを確認できます例えば16進数 8進数　指数などのフォーマット番号ですログ内のデータの可視性を管理するにはプライバシーオプションを使用しますロギングデータの個人情報を慎重に取り扱うことはとても重要ですなぜならアプリケーションが出荷されユーザの手元に届いた後もロギングが常に行われるからですデバイスとそのパスコードへの物理的なアクセス権を持つユーザがログを収集できますログのメッセージで個人情報を公開としてマークしなければログでの露出を防げます
実際にそれを行わずにパブリックを使用するのと同じ利点が等値保持ハッシュを使えば得ることができますこうすればデータの内容を明らかにしなくてもログのフィルタリングに有用なロギング値が一致するタイミングを把握できます例えばマスクパラメータを .privateプライバシーオプションに渡せば顧客の銀行口座番号をハッシュで記録できます口座番号を伏せたまま２つのログメッセージで同じ口座が参照されたタイミングが把握できます
ご紹介したLogger APIは iOS 14で利用可能です以前のリリースを対象とするアプリケーションの場合は printfスタイルのフォーマット文字列を受け入れるos_log関数を使いましょうこのリリース以降は Logger同様に文字列補間をos_log関数に渡すこともできます要約すると新しいSwiftロギングAPIを使えば問題のデバッグが可能ですそれ以外の方法では把握や修正を行うことはほぼ不可能ですバグを再現せずとも開発デバイスからログを取得して　ログにドリルダウンできるからですロギングAPIは高いパフォーマンスとリッチなフォーマッティングを兼ね備えていますしたがって情報メッセージをロギングできナレッジではエンドユーザに対してアプリケーションを遅延させることがありませんありがとうございました

2:44 - Example illustrating how to add logging to your app in three simple steps

// Add logging to your app in three simple steps
 
import os

let logger = Logger(subsystem: "com.example.Fruta", category: "giftcards")

func beginTask(url: URL, handler: (Data) -> Void) {
    launchTask(with: url) {
       handler($0)
    }

    logger.log("Started a task")
}

3:32 - An example code that logs a message with run-time data

// Add runtime data to the log messsage using string interpolation

import os

let logger = Logger(subsystem: "com.example.Fruta", category: "giftcards")

func beginTask(url: URL, handler: (Data) -> Void) {
    launchTask(with: url) {
       handler($0)
    }
    logger.log("Started a task \(taskId)")
}

4:28 - Example illustrating why nonnumeric types are redacted in the logs by default
```
logger.log("Paid with bank account \(accountNumber)")
```
5:01 - Code that shows how to mark public data so that it is displayed in the logs
```
logger.log("Ordered smoothie \(smoothieName, privacy: .public)")
```

6:03 - Code shown during first demo

import SwiftUI
import os

let logger = Logger(subsystem: "com.example.Fruta", category: "giftcards")

struct GiftCardView: View {
    // Denotes whether there is an active task for loading gift cards.
    @State private var taskRunning: Bool = false
    
    // A UUID that uniquely identifies a task.
    @State private var currentTaskID: UUID = UUID()
    
    // An unrecoverable error seen during execution.
    @State private var error: Error? = nil

    // A model that stores information about gift cards.
    @ObservedObject var model: GiftCardModel
    
    var body: some View {
        // Display a list of gifts which can be tapped on and scrolled through.
        GiftCardList(model: model, taskRunning: $taskRunning, currentTaskID: $currentTaskID, error: $error, downloadAction: beginTask, stopAction: endTask)
            .navigationTitle("Gift Cards")
    }
    
    // Start a task to download gift cards from a server.
    func beginTask(serverURL: URL, cardDownloadHandler: @escaping (Data) -> Void) {
        logger.log("Starting a new task for loading cards \(currentTaskID, privacy: .public)")        
        launchTask(with: serverURL) {
            cardDownloadHandler($0)
        }
    }
    
    // Stop the currently running task for downloading cards from a server.
    func endTask() {
        guard taskRunning else {
            logger.fault("Task \(currentTaskID, privacy: .public) is not runinng, cannot be stopped!")
            error = TaskError.noActiveTask
            return
        }
        taskRunning = false
        logger.log("Task \(currentTaskID, privacy: .public) interrupted")
    }
    
    // Start a URLSession dataTask with the given URL.
    func launchTask(with url: URL, handler: @escaping (Data) -> Void) {
        guard error == nil else {
            return
        }
        taskRunning = true
        let task = URLSession.shared.dataTask(with: url) {
            data, response, error in
            if let error = error {
                self.error = ConnectionError.other(error)
            }
            if let data = data {
                handler(data)
            }
        }
        task.resume()
    }

}

11:51 - Illustration of how debug-level logging will not evaluate the code that constructs log message
```
logger.debug("\(slowFunction(data))")
```

12:58 - Code that shows how to display run-time data with a fixed width and how to set precision of a floating-point value using formatting options

import SwiftUI
import os

let statisticsLogger = Logger(subsystem: "com.example.Fruta", category: "statistics")

// Log statistics about communication with a server.
func logStatistics(taskID: UUID, giftCardID: String, serverID: Int, seconds: Double) {
    statisticsLogger.log("\(taskID) \(giftCardID, align: .left(columns: GiftCard.maxIDLength)) \(serverID) \(seconds, format: .fixed(precision: 2))")
}

15:00 - Example of formatting log messages

logger.log("\(data, format: .hex, align: .right(columns: width))")

16:05 - Example illustrating the use of a hash to redact private data, which ensures that identical data get the same hash
```
logger.log("Paid with bank account: \(accountNumber, privacy: .private(mask: .hash))")
```

特定のトピックをお探しの場合は、上にトピックを入力すると、関連するトピックにすばやく移動できます。

クエリの送信中にエラーが発生しました。インターネット接続を確認して、もう一度お試しください。

リソース

関連ビデオ

WWDC23

WWDC20