Goのロギングライブラリ 2021年冬

この記事はPySpa Advent Calendar 2021の14日目のエントリーとして書かれました。昨日のエントリーは冷凍食品でウキウキ引きこもり生活 でした。ちなみに私も70ℓの冷凍庫を購入しましたが本当にライフチェンジングでした。

総論: なぜログが必要か

可観測性

たとえ目的は自明でも、その動作までが自明なアプリケーションというものはほぼ存在しません。現実の世界のアプリケーションというものは、動作パラメータだったり実行環境だったり、起動時点でのさまざまな要因によって挙動を変えるものだからです。そして、そうしたアプリケーションにはライフサイクルというものがあります。ここでいうライフサイクルは、アプリケーションの処理が実行されるにつれ、アプリケーションの内外との情報のやりとりで生じる大局的な状態の変化のことです。アプリケーションが並行処理を行うようなものであれば、個々の並行処理の単位にもライフサイクルがあることでしょう。アプリケーションはそれ単独で複雑な系であるということです。

また、現実の世界においては、単一のソフトウェアで自己完結するということも非常にまれなことです。どんなに単純なアプリケーションであっても、OSカーネルという異なるソフトウェアとの間でシステムコールなどの仕組みを用いコミュニケーションを行うことでその目的を果たすことになります。また、現代的なアプリケーションは、ネットワークを用いて他のアプリケーションと通信を行うことがしばしばあります。このような世界では、系の境界を単一のアプリケーションを含むだけに留めておくことは困難となります。そして、複数のソフトウェアを含む系では、ネットワーク理論を持ち出すまでもなく、複雑性も飛躍的に増大することは明らかです。

そうした複雑な系において、しばしば私たちはアプリケーションの予期しない動きに遭遇することがあります。予期しない動きは、アプリケーション内部の不具合によるものかもしれませんし、外部の不具合が理由なのかもしれません。限られた時間の中でその原因を切り分けするには、アプリケーションがある時点でどのような状態であったのかを時系列的に記録しておくことが必要になります。

記録する対象の粒度はさまざまです。アプリケーション単位であったり、アプリケーションを構成するモジュールやコンポーネントであったり、関数のコールグラフであったり、はたまたそれらの上に横断的に横たわる関心事であったりするでしょう。また、記録する対象も、数値、文字情報、バイナリ列であったりしますし、あるいはライフサイクルを構成する要素の時系列的な前後関係を表す、抽象的なものかもしれません。

現代では、こうした種々の時系列的な記録が運用で求められる文脈において充足していることを可観測性と呼んでいます。

可観測性とログ

アプリケーションを動かす環境、規模や、求められるサービスレベルの違いによって、可観測性に求められる要件というのも変わります。その上で、一部の組み込みシステムのような極端にリソースの制限がある環境を除き、あらゆる状況において、問題の原因を把握するという観点で最も原始的な方法であり、また重要となるのがログです。前述のようにアプリケーション一般が持つ構造によって与えられる文脈もありますが、アプリケーション固有の文脈は設計に依存するものであり、開発者が明示的に情報を出力するようにコードを記述してはじめて把握できるものとなります。とはいうものの、一方でログに出力する内容やログの出力箇所などの設計はプロジェクトを通して一貫させることが難しいという問題もあり、プログラマの属人的なものになる傾向があり、万能というわけではありません。その意味では客観性を担保できるメトリクスやトレースといった概念が際立ってくることでしょう。 (それらの概念もここで扱ってしまうと本稿の範囲を超えてしまうため、また別の機会に述べたいと思います。)

可観測性においてログが担うのは、一般的には記録の対象が主に文字情報、多くの場合自然言語の文として表現されているものの時系列的な集約です。本稿では特に断りを入れない限り、この意味でログという用語を用い、個々のイベントを記録する内容のことをログエントリー、ログエントリーに記録される文字情報をログメッセージということにします。

ログの機能

ラベリング、フォーマッター、構造化ロギング

ログはいわば航空機におけるフライトレコーダのようなもので、(パフォーマンスやセキュリティなど非機能要件上の要請が許す範囲内で) 量的な観点でも質的な観点でも、可能な限り情報を取捨選択したりせずに出力するべきですが、もちろん解析のためにログを見返すことになった際には検索や絞り込みを行うことになりますから、それらを容易にするような工夫もログのエントリに加えておく必要があります。

その工夫については、いくつかのプラクティスがあります。最も有名なプラクティスはいうまでもありませんが、ログを出力したアプリケーションから見て主観的な時刻をログエントリーに付加するというものです。現代的にログといえば、このラベルを欠くものはないといっていいでしょう。 (とはいえ、シェルベースのアプリケーションの多くで、出力にこのラベルを欠いています。)

次によく用いられるのは、ログレベルと呼ばれる重要度をログにラベリングする手法です。このログレベルの粒度はロギングフレームワークによって方針が異なることがありますが、概ね次のようなレベルが定義されていることが多いでしょう。

  • Fatal (致命的)

    アプリケーションの継続的な動作を脅かすような問題を報告するログエントリーに付加される重要度。

  • Error (エラー)

    アプリケーションを継続して動作させることは可能だが、予期しない事象が発生している旨を報告するログエントリーに付加される重要度。

  • Warning (警告)

    予期しない事象であるかどうかは文脈に依存するが、記録時点での状況がアプリケーションの設計から定義される平時のものではない旨を報告するログエントリーに付加される重要度。

  • Information (情報)

    上記のいずれでもなく、アプリケーションの動作に関わる情報のうち、将来の解析に有用であるようなものを記録するログエントリーに付加される重要度。

  • Debug (デバッグ)

    主に開発や不具合の解決時にデバッグなどの目的で動作を追跡するのに必要な文脈情報を記録するログエントリーに付加させる重要度。

他によく知られているラベリングは、ログを出力した関数名やソースコードのファイル名、出力箇所の行数などを出力するというものです。これに関しては、アプリケーションを記述するプログラミング言語の仕様や実行環境に依存するため、項目について共通認識があるというわけではありません。

いくつか汎用的なラベルを紹介してきましたが、よりアプリケーション依存ではあるものの有用なラベリングもあります。たとえばネットワークサーバーでは接続元のIPアドレスを記録しておくと良いでしょうし、ネットワークサーバーでもHTTPサーバであるならばHTTPメソッドやリクエスURIを記録しておくということもよく行われます。このように、ラベルの種類は文脈によってさまざまですが、解析の際にはラベルを手がかりに絞り込みを行なっていくことになりますから、ログエントリーを記録するときにはある一定の形式で格納することが求められます。

ログが文字情報を主体としていることから、伝統的にはログをテキストファイルとして各エントリを行指向で表現し、ファイルに記録したり、ストリームに出力することが多くあります。そうすることで、テキストファイルを対象とする一般的なユーティリティ、たとえばgrepsedといったコマンドを検索や絞り込みに活用することができるだけでなく、自作のプログラムでログを処理することが容易となるからです。その上でログメッセージに加え、複数のラベルを取り扱うとなると、各エントリが文字列として所定の形式になっていることが望ましくなってきます。そこで、多くのロギングフレームワークはログエントリーを所定の書式にて出力するためのフォーマッターというものを備えています。 (なお、呼称はフレームワークによって異なります。)

フォーマッターの仕様はロギングフレームワークによって変わりますが、おおむね次のような要素を備えています。

  • どのようにログエントリーを文字列として整形して出力するかを指示するための文字列
  • その文字列内に埋め込んで、任意の位置にログメッセージやラベルを出力することのできるプレイスホルダー文字列

プログラマがログエントリーに含めるように明示的に指定していないラベルもOOBデータ *1 として文字列に埋め込めるようにしているフォーマッターもあります。 (通常、時刻のようなラベルは明示的に含めるということはしないはずです。たとえば log4j2 のようなロガーは、時刻の他に、環境変数など実行環境に関わるラベルを含めることができるようにしています。)

フォーマッターは主に人間が目視しても判読できるような単純な文字列を生成することを目的としていますから、これを用いて表現できるラベルの種類はそう多くありません。複雑な文脈を表現する場合には、かつては限られたラベルの数の中で複数のログエントリーを出力することで対処してきましたが、現代的な運用環境においてはアプリケーションログはデータインジェスチョンを介して即時的にログ解析用のプラットフォームにストリーミングすることが増えてきており、そもそも人間が直接眺めるというところよりも、インジェスチョンが容易な形式で出力し、ひとつのログエントリーに可能な限り文脈を込めるというトレンドとなっています。そのトレンドの中で生まれたのが、構造化ロギングという考え方です。

構造化ロギングというからには、対になる概念として非構造化されたロギングがあるということですが、その非構造化されたものが伝統的なフォーマッターの出力する文字列ということになります。構造化されたロギングでは、プログラム的に処理しやすいJSON、MessagePack、ProtobufやCBORのようなデータモデルと表現形式のセットを前提として、文字列だけではなく、前提となるデータモデルの許す範囲でログエントリーを構成することができます。そのような状況では、ラベルの数に論理的な制約はありませんから、プログラマは任意にログエントリーに文脈情報として必要な数のラベルを追加できるのです。

エントリーポイントと設定の粒度

ロギングフレームワークにはログの記録に単一のエントリーポイント (ロガー) を提供するものと、フレームワークの利用者が複数のエントリーポイントを個別のロガーとして定義して、エントリーポイントごとにフォーマッターなどの設定を変えることができるようにしているものとがあります。このとき、多くのフレームワークではプログラム的にロガーを設定できるようにしていますが、外部ファイルなどを読み込んで設定することもできるようにしているものもあります。

前章で記録対象の粒度や関係性について少し触れましたが、事実多くのソフトウェアは、モジュールやコンポーネントといった構造を持っています。たとえば、アプリケーションとそれが利用するライブラリとは、最終的に同じプロセス空間で動くものの、コードの構成上は別のファイルだったり、プログラミング言語が定義するパッケージなどの別の論理的な区分であったりすることが多いでしょう。プログラミング言語によっては、こうしたモジュールやコンポーネントの関係性が階層構造をとるものがあります。この階層構造をロガーと対応づけて、ロガーの設定を階層構造の下から上に伝播 (propagate) することのできるようにしているものが存在します。これを階層ロギングなどと呼ぶことがあります。

Goのロギングライブラリ

GoのロギングライブラリはGoが誕生してからさまざまなものが作られてきましたが、大きく分けてZap以前とZap以後に分類できます。Zap以降のライブラリはほぼすべてがZapの設計を手本としているといっていいでしょう。Zapがなぜそれほど革新的であったかというと、パフォーマンスやAPIの利便性を犠牲にせず、むしろ従来型のライブラリよりもずっと高速に動作するにもかかわらず、構造化ロギングなど進歩的な機能を実装できていたからです。

Zap以前のロギングライブラリ / フレームワークは上に挙げた以外にも数多く存在しますが、メンテナンスが停止しているもの、とくにGoモジュールに対応していないものはあえてここでは取り上げないこととします。

前述の二分類とは別に、実装に依存しない (implementation agnosticな) ファサードとしてのAPI (他の言語、たとえばJavaでいうところのslf4jのようなライブラリです) を提供するライブラリもあります。そうしたライブラリで最も著名なのがgo-logr/logrです。go-logr/logrAPIを使ってロギングを実施しておけば、Logrus、ZapやZeroLogを含む複数のロギングフレームワークをバックエンドとして切り替え可能となります。logrのようなライブラリはアプリケーションの中で使うというよりも、ライブラリの作者が、その中でロギングを実施する想定であるけれども、特定のロガーの実装に依存するのを避け、ライブラリの利用者の裁量で実装を選べるようにしたいと考えている時に特に有用です。

早見表

- 複数のロガーのインスタンス ログレベルに基づくロギング フォーマッタの変更 構造化ロギング JSON形式での出力 ターミナルに色付きで出力 ゼロアロケーション サンプリング
標準のlogパッケージ ✔︎ 一部可
google/logger ✔︎ ✔︎ 一部可
golang/glog ✔︎
k8s.io/klog ✔︎ デフォルトでも一部可だが、logr経由で出力することで全面的に可能 ✔︎ ︎logr経由で出力することで可能 logr経由で出力することで可能
Logrus ✔︎ ✔︎ ✔︎ ✔︎ ✔︎ ✔︎
apex/log ✔︎ ✔︎ ✔︎ ✔︎ ✔︎ ✔︎
Zap ✔︎ ✔︎ ✔︎ ✔︎ ✔︎ ✔ (Windowsで使うには工夫が必要) ︎✔︎
ZeroLog ✔︎ ✔︎ ✔︎ ✔︎ ✔︎ ︎✔︎
RipZap ✔︎ ✔︎ ✔︎ ✔︎ ✔︎ ✔ (Windowsで使うには工夫が必要) ︎✔︎ ✔︎

標準のlogパッケージ

サンプルコード

package main

import (
    "log"
    "os"
)

// 出力:
// [my-app] 2021/12/12 15:13:02 /tmp/standard-log/test.go:12: Hello 世界
// [my-app] 2021/12/12 15:13:02 /tmp/standard-log/test.go:13: Hello地球
// 2021/12/12 15:13:02.293092 test.go:17: [my-app] Hey 世界
// 2021/12/12 15:13:02.293095 test.go:18: [my-app] Hey地球
func main() {
    // デフォルトのロガーを用いたログ出力
    // フォーマットの変更
    log.SetFlags(log.Llongfile | log.LUTC | log.LstdFlags)
    log.SetPrefix("[my-app] ")
    log.Println("Hello", "世界")
    log.Print("Hello", "地球")

    // ロガーのインスタンスを生成
    myLogger := log.New(
        os.Stdout, "[my-app] ",
        log.Ldate | log.Lmicroseconds | log.Lshortfile | log.LUTC | log.Lmsgprefix,
    )
    myLogger.Println("Hey", "世界")
    myLogger.Print("Hey", "地球")
}

プロフィール

レポジトリ: go.googlesource.com

ドキュメント: pkg.go.dev

初コミット: 2009年1月27日 (Goのリリースは2009年11月)

執筆時点での最終リリース: (Go本体のリリースと同じ)

Goの標準ライブラリとして提供されているロギングライブラリです。作者はrscことラス・コックス氏です。果たして人類にログレベルは早すぎるという思想があるのかわかりませんが、今回紹介するロギングライブラリの中で唯一ログレベルに対応していません ((厳密にはFatal()Panic()をログレベルという扱いにすれば3段階あることになる))。

グローバル関数をエントリーポイントとして使うことのできるデフォルトのロガーと、New()関数を通じてインスタンスを生成し、個別に出力フォーマットなどの設定が可能な、メソッドがエントリーポイントとなっている*LoggerAPIの二本立てとなっています。

フォーマッターの実装は固定ですが、SetFlags()関数 / メソッドを通じてある程度フォーマットの変更が可能です。SetPrefix() 関数 / メソッドまたはNew()関数の引数でログエントリーの中に任意の固定文字列を含めることも可能です。

...()...ln() の違いは、どちらも引数が複数指定されるとそれらの引数を文字列化したものを結合して出力するのですが、そこで文字列と文字列の間にスペースを入れる (...ln()) か入れない (...()) という点です。また、...f()を用いると、fmt.Printf()と同様の書式文字列を用いてログメッセージを組み立てることが可能です。

Print...()Fatal...() Panic...() の違いは、Print...()がログエントリーを出力後ただちに呼び出し元に復帰するのに対して、Fatal...()はログエントリーを出力後終了ステータス1でプロセスを終了し、Panic...()はログエントリーを出力後panicを発生させてプロセスを終了するという点です。

google/logger

サンプルコード

package main

import (
    "io"
    "log"

    "github.com/google/logger"
)

// 出力:
// ERROR: 2021/12/13 10:17:35 /tmp/google-log/test.go:15: いきなりですが宇宙ヤバイ
// INFO : 2021/12/13 10:16:45 /tmp/google-log/test.go:15: Hello 宇宙
// INFO : 2021/12/13 19:16:45.237126 test.go:22: Hey 宇宙
// INFO : 2021/12/13 19:16:45.237153 test.go:28: Info verbosity set to 2
// INFO : 2021/12/13 19:16:45.237165 test.go:29: Hey世界
// INFO : 2021/12/13 19:16:45.237172 test.go:30: Hey地球
func main() {
    // デフォルトのロガーを用いたログ出力
    // 第4引数はログファイルの出力先を表すio.Writerなので、
    // io.Discard (ioutil.Discard) を指定すると標準出力やシステムロガー以外に出力されなくなる
    logger.Init("my-app", true, false, io.Discard)
    // フォーマットの変更
    logger.SetFlags(log.Llongfile | log.LUTC | log.LstdFlags)
    logger.Error("いきなりですが", "宇宙", "ヤバイ")
    logger.Infoln("Hello", "宇宙")
    logger.V(1).Info("Hello", "世界")
    logger.V(2).Info("Hello", "地球")

    // ロガーのインスタンスを生成
    myLogger := logger.Init("my-app", true, false, io.Discard)
    logger.SetFlags(log.Ldate | log.Lmicroseconds | log.Lshortfile | log.LUTC)
    myLogger.Infoln("Hey", "宇宙")
    // デフォルトのログレベル (verbosity) は0のため、下の2つは表示されない
    myLogger.V(1).Info("Hey", "世界")
    myLogger.V(2).Info("Hey", "地球")

    // ログレベル (verbosity) を1に設定
    myLogger.SetLevel(2)
    myLogger.V(1).Info("Hey", "世界")
    myLogger.V(2).Info("Hey", "地球")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

初コミット: 2016年2月11日

執筆時点での最終リリース: 2021年5月8日 (v1.1.1)

シンプルで保守的な実装とGoogleの公式GitHubレポジトリ配下にあることからとても古いライブラリのように思えますが、なんと初コミットは2016年です。歴史的に見るとgolang/glogの方が先にリリースされているにもかかわらず、このライブラリをあえて実装したモチベーションはやや謎に包まれています *2

APIはおおむね標準のlogパッケージをなぞったものとなっていますが、GoogleC++ロギングライブラリであるglogと同様のセマンティクスを持ったログレベルに対応している点でより実用的といえます。glogと同様のセマンティクスというのは、この後に紹介するgolang/glogとおおむね同じなのですが、ログレベルだけでログの詳細度 (verbosity) を区別するのではなく、ログの深刻度 (severity) と詳細度 (verbosity) とを概念上区別しているというものです。ログの深刻度としてはInfo、Warning、Error、Fatalの4つを定義していて、ログの詳細度は深刻度がInfoの場合に限り無段階で指定することができます。ややこしいことに、このパッケージの「ログレベル」という表現は実際には詳細度を意味していますので留意が必要です。また、深刻度に応じてログエントリの出力を行うか行わないかを制御するといったことはできません。

ログエントリーはどのような設定を行っても必ず標準出力か標準エラー出力に出力されます。どちらが選ばれるかはログの深刻度により、ErrorやFatalに関しては標準エラー出力に、WarningやInfoについては標準出力に書くようになっています。これもC++のglogのポリシーをなぞったのものになっています。

logパッケージと同様Init()というファクトリ関数があり、個別のロガーのインスタンスを生成することができ…るのですが、設計が度し難く、Init()の初回の呼び出しはデフォルトのロガーの初期化を意味し、2回目以降の呼び出しでインスタンスが生成できるようになるという仕様となっています。さらに信じられないことには、logパッケージに定義されたものと同じフラグでフォーマットを変更できるのですが、なんとこのフォーマットはロガーのインスタンスごとではなくグローバルにしか変更できない仕様となっています。

他のロギングライブラリにない特色として、OSのシステムロガー (Windowsであればイベントログ、Linuxなどであればsyslog) にもログエントリを出力することができるという点があります。デフォルトロガーのデフォルトの設定では、システムロガーにもログエントリを出力するようになっていますので注意してください。Init() 関数の第3引数は systemLog bool で、これを true にするとシステムロガーの出力が有効になり、 false にすると無効となります。

Init()関数の第4引数にio.Writerインターフェイスを持ったオブジェクトを指定すると、標準 (エラー) 出力やシステムロガーに加えて、そのオブジェクトの表す出力先にも (teeコマンドのように) ログエントリを出力できるようになっています。いずれにしても標準 (エラー) 出力への出力は止めることができません。

良いところ・特徴

  • 標準のlogモジュール並みのシンプルさでログレベルが付加されたログを扱うことができる。
  • ロガーの設定をコマンドラインから受け取ってよしなに設定をしてくれるため、設定を行うコードを自分で書かなくても済む。
  • 別ライブラリの助けなどを借りずにシステムログにもログを出力できる。
  • 公式っぽい雰囲気で安全安心。

良くないところ

  • 出力先のコントロールがそれほど柔軟ではない。あくまで標準出力への出力は強制。
  • フォーマッターが固定で任意の出力にできない。
  • 任意のラベリングができず、当然構造化ロギングにも対応していない。
  • 複数の言語を用いているプロジェクトの場合、他の言語のロギングフレームワークのセマンティクスと異なる部分があり、調整が難しいかもしれない。

golang/glog

サンプルコード

package main

import (
    "flag"

    "github.com/golang/glog"
)

func init() {
    flag.Parse()
}

// go run test.go -logtostderr=true -v=2を指定したときの出力:
// I1213 22:38:05.617805    4014 test.go:17] Hello地球
// I1213 22:38:05.617944    4014 test.go:18] Hello 世界
// I1213 22:38:05.617948    4014 test.go:19] Hey地球
// I1213 22:38:05.617951    4014 test.go:20] Hey世界
// W1213 22:38:05.617954    4014 test.go:22] 警告
// E1213 22:38:05.617957    4014 test.go:23] エラー
// F1213 22:38:05.617959    4014 test.go:24] 致命的エラー
// exit status 255
func main() {
    defer glog.Flush()
    glog.V(1).Info("Hello", "地球")
    glog.V(2).Info("Hello", "世界")
    glog.Warning("警告")
    glog.Error("エラー")
    glog.Fatal("致命的エラー")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

初コミット: 2013年7月16日

執筆時点での最終リリース: 2021年8月20日 (v1.0.0) (これがgo modulesに対応した初リリース)

Google謹製のC++用ロギングフレームワークであるglogのGo版というような位置づけで開発が開始されたものとみられますが本当の理由は不明です。

github.com/golang/ 配下にありますが、これはgo.googlesource.comにあるGoogleのプロダクトではなくGoコミュニティによって開発されているようです。とはいえ、ロブ・パイク氏をはじめとするGoのコアメンバーも開発に参加しているので、準公式くらいの位置づけといっても過言ではないでしょう。

ロガーの設定はC++のglogと同じようにコマンドラインから行うようになっています。オプション名と意味もほぼC++版と同じですが、コマンドラインフラグに前置される-の数がC++では2つなのに対してGo版は1つとなっており、完全な互換性があるとはいえません。ログの詳細度は実行時にも変更することはできますが、残念なことに他の設定はコマンドライン以外から変更できません。

ログレベルについてはC++版のglogと同様の独特のポリシーに基づいており、出力対象となるログエントリーの詳細度も-v=詳細度のように-vオプションで指定可能です。C++版のglogでは実装されていたにもかかわらずgoogle/loggerにはされていなかった、呼び出し箇所 (コールサイト) ごとにログの詳細度を指定するという機能も-vmoduleオプションを通じて利用可能です。 このオプションに与える値は、パターン=詳細度の対を,区切りで-vmodule=main=1,foo*=2のように指定します。パターンに指定するのはfilepath.Match()関数に指定できる文字列と同じもので、パターンマッチは各ソースファイルのパス名に対し、ディレクトリを含まないファイル名から.goを取り除いたものに対して行われます。

デフォルトのログ出力先はglogと同じようにテンポラリディレクトリ内のファイルで、os.TempDir()で取得したディレクトリとなります。テンポラリディレクトリではなく明示的にディレクトリを指定するにはコマンドライン-log_dirオプションを-log_dir=ディレクトリ名のように指定します。ログファイルは深刻度別に生成され、所定の条件でローテートします。もし-log_dirを指定していた場合で、当該ディレクトリにファイルの生成ができなかった場合はデフォルト同様にテンポラリディレクトリを使います。

ファイルに加えて、深刻度がErrorまたはFatalの場合は標準エラー出力にもログエントリーが出力されます。ただし、深刻度がWarningとInfoの場合はgoogle/loggerと異なり、出力先がファイルのみとなります。この動作は -logtostderr=true または -alsologtostderr=trueを指定することで変更可能ですが、指定した場合はInfoのログエントリーも標準出力ではなくすべて標準エラー出力から出力されます。

標準のlogパッケージやgoogle/loggerと違って、複数のロガーのインスタンスを作ることはできません。グローバルなロガー1つのみを扱うことができます。

CopyStandardLogTo()関数を呼び出すことで、標準のlogパッケージの出力をこのライブラリ経由させてファイルに出力することもできます。

上に挙げた以外にもコマンドラインオプションがいくつか存在しますが、詳細はドキュメントを参照してください。

良いところ・特徴

  • 標準のlogモジュール並みのシンプルさでログレベルが付加されたログを扱うことができる。
  • ロガーの設定をコマンドラインから受け取ってよしなに設定をしてくれるため、設定を行うコードを自分で書かなくても済む。
  • 呼び出し箇所 (コールサイト) ごとにログの詳細度を指定することができる。
  • デフォルトでファイルにローテートログを出力してくれる。

良くないところ

  • ロガーの設定をコマンドラインから設定をするところ。
    • 標準の flag パッケージを用いてコマンドラインをパースするため、他のライブラリを使うことができない。
    • init() の中などで flag.Parse() の呼び出しが必要。
  • デフォルトのロガーの出力が標準出力ではなくテンポラリディレクトリであるところ。
  • フォーマッターが固定で任意の出力にできない。
  • 任意のラベリングができず、当然構造化ロギングにも対応していない。
  • 複数の言語を用いているプロジェクトの場合、他の言語のロギングフレームワークのセマンティクスと異なる部分があり、調整が難しいかもしれない。

k8s.io/klog

サンプルコード

package main

import (
    "flag"

    "k8s.io/klog/v2"
)

func init() {
    // initで呼び出しているが、以下は最初のログを書き出す前であればどこで実行してもよい
    flagset := flag.NewFlagSet("", flag.ContinueOnError)
    klog.InitFlags(flagset)
    // "-v=2" とすると "Hey from 地球" のログエントリーも表示される。
    flagset.Parse([]string{"-v=1"})
}

// 出力:
// I1213 22:39:14.549553    4065 test.go:17] "Hello 地球" type="greeting" target="planet"
// I1213 22:39:14.549654    4065 test.go:18] "Hello from 地球" type="greeting" sender="planet"
// I1213 22:39:14.549661    4065 test.go:19] "Hey 地球" type="greeting" target="planet"
func main() {
    defer klog.Flush()
    klog.InfoS("Hello 地球", "type", "greeting", "target", "planet")
    klog.InfoS("Hello from 地球", "type", "greeting", "sender", "planet")
    klog.V(1).InfoS("Hey 地球", "type", "greeting", "target", "planet")
    klog.V(2).InfoS("Hey from 地球", "type", "greeting", "sender", "planet")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

初コミット: 2018年10月26日

執筆時点での最終リリース: 2021年10月22日 (v2.30.0)

golang/glogのフォークです。かつてKubernetesではglogを使っていましたが、このissueで議論が行われ、独自にメンテナンスすることになったようです。

Issueで挙げられていた問題とは以下のようなものです。

  • Kubernetesではgithub.com/spf13/cobraなどのコマンドラインパーサーを使っていることもあり、flag.Parse()を呼び忘れることがしばしばある。また、実行時に設定を変更する術がない。
  • ファイルにログが出力されるというglogのデフォルトの挙動は、ライブラリのユーザーが通常期待するものではなく、ファイルに書き出したいのであれば明示的に設定するものと考えるだろう。
  • もしログを作ることができなければglogはos.Exit()を読んでその時点でプロセスを終了してしまう。これはとても危険なことだ。
  • glogは書き出されたファイルを管理したりしないので、logrotateのような仕組みが別途なければひたすらファイルが蓄積していくことになる。 (とくにコンテナの中では問題である)
  • glogの出力をテストできない。
  • 出力先のディレクトリは指定できるが、特定のファイルに出力することができない。

この問題を解消するために、k8s.io/klogでは次のような改善が行われました。

良いところ・特徴

  • golang/glogをコンテナ環境で使う上での欠点が解消されている。
  • コマンドラインからではなくプログラム的にロガーの設定ができる。
  • golang/glogAPIレベルの互換性がある。
  • 構造化ロギングに対応している。
  • go-logr/logrを経由した出力が可能で、自由にロギングの実装を差し替えることができる。

良くないところ

  • ドキュメントがない。
  • 設定方法がいまだに flag パッケージに引きずられている。
  • 複数の言語を用いているプロジェクトの場合、他の言語のロギングフレームワークのセマンティクスと異なる部分があり、調整が難しいかもしれない。

Logrus

サンプルコード

package main

import (
    "github.com/sirupsen/logrus"
)

// 出力:
// INFO[2021-12-13T22:54:04+09:00] Hello地球
// INFO[2021-12-13T22:54:04+09:00] Hello地球                                       target=planet
// INFO[2021-12-13T22:54:04+09:00] Hello地球                                       target=planet
// INFO[2021-12-13T22:54:04+09:00] Goodbye地球                                     target=planet
// {"level":"info","msg":"Hello again 地球","time":"2021-12-13T22:54:04+09:00"}
func main() {
    // テキスト形式で出力する
    logrus.SetFormatter(
        &logrus.TextFormatter{
            FullTimestamp: true,
        },
    )
    // ログレベルがDEBUG以上の場合には出力する
    logrus.SetLevel(logrus.DebugLevel)
    logrus.Info("Hello", "地球")
    logrus.WithFields(
        logrus.Fields{
            "target": "planet",
        },
    ).Info("Hello", "地球")

    contextual := logrus.WithFields(
        logrus.Fields{
            "target": "planet",
        },
    )

    contextual.Info("Hello", "地球")
    contextual.Info("Goodbye", "地球")

    // JSON形式で出力する
    logrus.SetFormatter(&logrus.JSONFormatter{})
    logrus.Infoln("Hello", "again", "地球")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

最初のコミット: 2013年10月17日

執筆時点での最終リリース: 2021年5月9日 (v1.8.1)

Goのロギングライブラリ界の中では老舗でかつもっとも広く使われることになったライブラリです。READMEにあるように、すでにこのライブラリはメンテナンスモードに入っていて、作者自身がZeroLogやZapやApexの利用も提案しています。

機能としてはそつなく構造化ロギングに対応していたり、フォーマッターの実装を差し替えることができたりしますし、ターミナルへの出力時にログエントリに色をつけたりすることもできます。デフォルトでは標準エラー出力にログエントリーを出力するようになっています。グローバルなデフォルトロガーとは別に、ロガーのインスタンスを複数作ることもできます。特徴的なものとしては、フック (Hook) という仕組みがあり、これを使うとログレベルごとに異なる出力先を指定したり、ログエントリーにフィルターを施したりすることができます。

Zap以降のロギングライブラリのベンチマークでよくサンドバックとして名前が挙げられるぐらい遅さが指摘されることがありますが、実用上問題になることはほとんどないでしょう。とはいえ、速いに越したことはありませんし、あえて今Logrusを選ぶ必要がないのも事実です。

良いところ・特徴

  • よく使われている (いた)。
  • ドキュメントがよく書かれている。
  • 構造化ロギングに対応している。
  • JSON形式のフォーマッターがついてくる。
  • 他の言語のロギングライブラリと同様のセマンティクスを持ったログレベルを持っている。

良くないところ

  • (些細なことですが) デフォルトのフォーマッターが時刻を表示しないところ。
  • Zapなどのライブラリと比較して遅い。

Apex

サンプルコード

package main

import (
    "github.com/apex/log"
    "github.com/apex/log/handlers/json"
    "github.com/apex/log/handlers/text"
)

// 出力:
//   INFO[0000] Hello 地球
//   INFO[0000] Hello 地球                  target=planet
//   INFO[0000] Hello 地球                  target=planet
//   INFO[0000] Goodbye 地球                target=planet
//   INFO[0000] span
//   INFO[0001] span                      duration=1002
// {"fields":{},"level":"info","timestamp":"2021-12-13T23:47:36.174844+09:00","message":"Hello again 地球"}
func main() {
    // テキスト形式で出力する
    log.SetHandler(text.Default)
    // ログレベルがDEBUG以上の場合には出力する
    log.SetLevel(log.DebugLevel)
    log.Info("Hello 地球")
    log.WithField("target", "planet").Info("Hello 地球")

    contextual := log.WithFields(
        log.Fields{
            "target": "planet",
        },
    )

    contextual.Info("Hello 地球")
    contextual.Info("Goodbye 地球")

    func() {
        defer log.Trace("span").Stop(nil)
        time.Sleep(time.Second)
    }()

    // JSON形式で出力する
    log.SetHandler(json.Default)
    log.Info("Hello again 地球")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev Medium

最初のコミット: 2015年12月22日

執筆時点での最終リリース: 2020年8月18日 (v1.9.0)

Logrus以降、Zap以前に登場したライブラリです。APIはLogrusと非常によく似たものとなっていますが、いくつか異なる特徴もあります。主なものとしては

  • 構造化ログを出力する上でより効率的な WithField()メソッド。
  • ロギングライブラリの中からトレースを考慮したTrace()メソッドの提供。

があります。その他の特徴として、出力先のバックエンドを変更可能なHandlerの実装が挙げられます。標準でElasticsearchやAmazon Kinesis用のハンドラーも提供されています。

残念ながらLogrus同様、今となっては積極的に選択する理由はないように思います。

良いところ・特徴

  • Logrusとある程度APIの互換性があるのでそのまま置き換えができる。
  • 簡易的なトレースに対応している。
  • 標準でいくつかのハンドラーが提供されている。

良くないところ

  • 標準のlogパッケージとの互換性がない。
  • textハンドラーの実装がひどくWindowsに正しく対応できていない。 (cliハンドラーは対応している。)
  • textハンドラーの時刻のフォーマットを変更できない。

Zap

サンプルコード

package main

import (
    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
)

// 出力:
// {"severity":"INFO","timestamp":"2021-12-06T08:22:45.9488001+09:00","go.uber.org/zap/caller":"test.go:47","permanent":"value","type":"greeting","target":"planet"}
// {"severity":"ERROR","timestamp":"2021-12-06T08:22:45.9488664+09:00","go.uber.org/zap/caller":"test.go:56","permanent":"value","type":"greeting","target":"planet","go.uber.org/zap/stacktrace":"main.main\n\t/home/moriyoshi/src/zap-test/test.go:56\nruntime.main\n\t/home/moriyoshi/opt/go-1.17.3/src/runtime/proc.go:255"}
// {"severity":"FATAL","timestamp":"2021-12-06T08:22:45.9488874+09:00","go.uber.org/zap/caller":"zap/test.go:63","permanent":"value","type":"greeting","target":"planet","go.uber.org/zap/stacktrace":"main.main\n\t/home/moriyoshi/src/zap-test/test.go:63\nruntime.main\n\t/home/moriyoshi/opt/go-1.17.3/src/runtime/proc.go:255"}
// exit status 1
func main() {
    // クイックに使うのであれば
    // logger := zap.NewDevelopmentConfig()
    // などとすればいい

    // 手でconfigをビルドする場合
    logger, err := zap.Config{
        Level: zap.NewAtomicLevelAt(zap.DebugLevel),
        Development: true,
        Encoding: "json",
        EncoderConfig: zapcore.EncoderConfig{
            TimeKey: "timestamp",
            LevelKey: "severity",
            NameKey: "go.uber.org/zap/logger",
            CallerKey: "go.uber.org/zap/caller",
            FunctionKey: zapcore.OmitKey,
            StacktraceKey: "go.uber.org/zap/stacktrace",
            LineEnding: zapcore.DefaultLineEnding,
            EncodeLevel: zapcore.CapitalLevelEncoder,
            EncodeTime: zapcore.RFC3339NanoTimeEncoder,
            EncodeDuration: zapcore.SecondsDurationEncoder,
            EncodeCaller: zapcore.ShortCallerEncoder,

        },
        OutputPaths: []string{"stderr"},
        ErrorOutputPaths: []string{"stderr"},
    }.Build(
        zap.AddCaller(),
        zap.Fields(
            zap.String("permanent", "value"),
        ),
    )

    if err != nil {
        panic(err)
    }

    defer logger.Sync()

    logger.Info(
        "Hello 地球",
        zap.String("type", "greeting"),
        zap.String("target", "planet"),
    )

    sugaredLogger := logger.Sugar()

    // sugaredLoggerは少しだけ遅いが記述量は減る
    sugaredLogger.Errorw(
        "Hey 地球",
        "type", "greeting",
        "target", "planet",
    )

    // Fatalを呼び出すとスタックトレースを出力してプロセスは終了する   
    logger.Fatal(
        "Goodbye 地球",
        zap.String("type", "greeting"),
        zap.String("target", "planet"),
    )
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

最初のコミット: 2016年2月20日

執筆時点での最終リリース: 2021年9月9日

このライブラリの特徴は、なんといっても速さです。メモリアロケーションを最小限に止めるために独自にJSONエンコーダーを実装するなどして、いくつかのケースではゼロアロケーションを達成できています。ロガーの実装としては、記述は最低限になるが低速なSugaredLoggerと、記述量は若干増えますが高速なLoggerが提供されています。他のロギングライブラリと違い、グローバルなデフォルトロガーは提供されていませんが、RedirectStdLog関数を呼び出すことで、標準のlogパッケージのログエントリーをZapに流すことができます。

フォーマッターの設定は、Config構造体に値を設定しBuild()メソッドを呼ぶことによって行います。JSON形式やテキスト形式など根本的なログ形式を設定するにはConfig.Encodingエンコーダー名を指定し、個々の要素の表現形式を指定するにはConfig.EncoderConfigを変更します。標準ではEncodingに指定できるエンコーダー名としてはjsonconsoleの2種類がありますが、完全にカスタマイズしたエンコーダーを使いたい場合はEncoderインターフェイスを実装するオブジェクトを返す関数をRegisterEncoderで登録することで行います。ログレベルや時刻といった要素のエンコーダーはそれぞれEncoderConfig構造体のEncodeLevel EncodeTime を変更することで可能です。

Logrusと似たようなフック機構があり、以下のようにしてフック関数を登録するとログエントリーが書き込まれる直前に何らかの処理を実行することが可能です。しかし、Logrusと違ってログエントリーを表すEntry構造体そのものに手を加えることはできません。ドキュメントにもありますが、エントリーに手を加える場合にはzapcore.Coreを実装して差し替えることになります。

// ログレベルごとに出力数を数える例
var mu sync.Mutex
count := make(map[zapcore.Level]int)

newLogger := logger.WithOptions(
    // `zap.Hooks()`は`Option`のビルダー関数なので、`Config.Build()`関数の引数に渡してもよいです
    zap.Hooks(
        func(e zapcore.Entry) error {
            // ログの出力の都度呼ばれます
            mu.Lock()
            count[e.Level] += 1
            mu.Unlock()
            return nil
        },
    ),
)

上記以外に実践的な機能としては条件サンプリングが挙げられます。条件サンプリングとは、与えられた条件を満たす場合のみログエントリーの出力を行うというもので、高頻度にログの書き出しが発生しパフォーマンス上影響が出るような状況で有用です。サンプリングの設定はConfig構造体に行います。

   logger, err := zap.Config{
        Level: zap.NewAtomicLevelAt(zap.DebugLevel),
        Development: true,
        Encoding: "json",
        EncoderConfig: zapcore.EncoderConfig{...},  // ...の部分は省略を表しています
        Sampling: &SamlingConfig{
            Initial: 50,  // 最初の50エントリーをすべて出力するが
            Thereafter: 10,  // 以降は10エントリーおきに出力する
        },
        OutputPaths: []string{"stderr"},
        ErrorOutputPaths: []string{"stderr"},
    }.Build(...)  // ...の部分は省略を表しています

良いところ・特徴

  • とにかく速い。
  • 構造化ロギングを初めから見据えたAPIとなっている。
  • フォーマッターのカスタマイズ性が高い。
  • 条件サンプリングに対応している。
  • ドキュメントがある程度充実している。

良くないところ

  • もしプリセットのロガーの設定 (NewExampleConfig() NewDevelopmentConfig() NewProductionConfig()) を用いない場合はConfig構造体を利用者が組み立てる必要があるが、項目が多く煩雑である。
  • 色付きの出力の実現が雑にANSIエスケープシーケンスを出すだけとなっている。Windowsに対応したい場合はmattn/go-colorableを利用する必要がある。

ZeroLog

サンプルコード

package main

import (
    "github.com/rs/zerolog/log"
)

// 出力
// {"level":"info","type":"greeting","target":"planet","time":"2021-12-06T20:27:36+09:00","message":"Hello 地球"}
// {"type":"greeting","target":"planet","time":"2021-12-06T20:27:36+09:00","message":"Hello 地球"}
// {"level":"fatal","time":"2021-12-06T20:27:36+09:00","message":"Goodbye 地球"}
// exit status 1
func main() {
    log.Info().Str(
        "type", "greeting",
    ).Str(
        "target", "planet",
    ).Msg(
        "Hello 地球",
    )

    ev := log.Log().Fields(
        []interface{}{
            "type", "greeting",
        },
    )

    ev.Str("target", "planet").Msg("Hello 地球")

    // Fatalを呼び出すとスタックトレースを出力してプロセスは終了する
    log.Fatal().Msg("Goodbye 地球")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

最初のコミット: 2017年5月14日

執筆時点での最終リリース: 2021年11月2日 (v1.26.0)Twitterで誤認を指摘いただきました。ありがとうございました。

Zap以降に開発されたライブラリで最も利用されているものがこのZeroLogと言えるでしょう。もうZapでいいじゃないかと言わせない魅力がこのライブラリにはあります。Zapは機能が豊富ですが、ロガーを使い始めるまでにかなりの手続きを踏む必要がありました。ZeroLogはZapほどの機能は備えていませんが、ほとんどのユースケースで必要十分と思われるずっとシンプルなAPIを提供しています。Zapにはなかったグローバルのデフォルトロガーも提供されています。Hookやサンプラーといった機構もあります。

Zapと大きく思想的に異なるのは、ログエントリーの組み立てに可変引数の代わりにメソッドチェインを用いるところです。Goの言語的な特徴から、メソッドチェインはは可読性が低くなりがちではあるので、この部分はかなり好みが分かれるところでしょう。

事情は分かりませんが、他のロギングライブラリと違い、CBOR形式での出力を行えるフォーマッターが標準で提供されています。

良いところ・特徴

  • 標準のlogパッケージと一部互換性がある。
  • おおむね速い。
  • 構造化ロギングを初めから見据えたAPIとなっている。
  • メソッドチェインを使ってログエントリーを組み立てるところ。
  • 詳細なドキュメントが不要なくらいAPIがシンプル。
  • グローバルのデフォルトロガーがある。
  • 条件サンプリングに対応している。
  • Zapよりもフットプリントが小さい。
  • Debugレベルの下のログレベルとしてTraceが定義されている。

良くないところ

  • フォーマッターのカスタマイズ性が低い。
  • フォーマッター以外にも細かい設定がZapほどはできない。
  • メソッドチェインを使うところ。

RipZap

サンプルコード

package main

import (
    "github.com/skerkour/rz"
    "github.com/skerkour/rz/log"
)

// 出力:
// {"level":"info","type":"greeting","target":"planet","timestamp":"2021-12-06T11:42:11Z","message":"Hello 地球"}
// {"level":"info","type":"greeting","target":"planet","timestamp":"2021-12-06T11:42:11Z","message":"Hello 地球"}
func main() {
    log.Info(
        "Hello 地球",
        rz.String("type", "greeting"),
        rz.String("target", "planet"),
    )

    log.SetLogger(
        log.With(
            rz.Fields(
                rz.String("type", "greeting"),
                rz.String("target", "planet"),
            ),
        ),
    )

    log.Info("Hello 地球")
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

最初のコミット: 2018年7月24日

執筆時点での最終リリース: 2021年8月11日 (v1.0.1)

もともと作者は匿名性の高い活動を bloom42 (a.k.a. z0mbie42) のハンドルで行っていて、 github.com/bloom42/rz-go というレポジトリでリリースしていたのですが、ある時から諸事情があったらしく本名で活動するようになり、その際にGitHubアカウントもレポジトリも github.com/skerkour/rz に移動したという経緯があります。なので、現状fork数もstar数もとても少ないですが、それなりに使われてはいます。

ZapやZeroLog同様Hookやサンプラーインターフェイスも備えています。

良いところ・特徴

  • Zapスタイルのフィールド指定方法が扱えながら、ZeroLogのようなグローバルのデフォルトロガーが提供されている、いいところ取り感。
  • ベンチマークが行われており、ZapやZeroLogに匹敵する速度で動作する。
  • フォーマッターの差し替えが可能。

良くないところ

  • github.com/bloom42/rz-go からレポジトリの変更が行われた際にバージョンのリセットが行われてしまい、v2.6.1をv1.0.0にするという蛮行が行われたので、すんなり go get (なり go mod tidy なり) で入らなくなってしまった。
  • console用フォーマッターが雑にANSIエスケープシーケンスを出力しているのでWindowsに対応したい場合はmattn/go-colorableを利用する必要がある。

go-logr/logr

サンプルコード

package main

import (
    "github.com/go-logr/logr"

    "github.com/go-logr/zapr"
    "github.com/go-logr/zerologr"
    zerolog_log "github.com/rs/zerolog/log"
    "go.uber.org/zap"
)

// {"level":"debug","msg":"Hello 地球","type":"greeting","target":"planet"}
// {"level":"debug","v":1,"type":"greeting","target":"planet","time":"2021-12-06T21:21:31+09:00","message":"Hello 地球"}
// {"level":"trace","v":2,"type":"greeting","target":"lands","time":"2021-12-06T21:21:31+09:00","message":"Hello 世界"}
func main() {
    var log logr.Logger

    log = zapr.NewLogger(zap.NewExample())
    log.V(1).Info(
        "Hello 地球",
        "type", "greeting",
        "target", "planet",
    )
    log.V(2).Info(
        "Hello 世界",
        "type", "greeting",
        "target", "lands",
    )

    log = zerologr.New(&zerolog_log.Logger)
    log.V(1).Info(
        "Hello 地球",
        "type", "greeting",
        "target", "planet",
    )
    log.V(2).Info(
        "Hello 世界",
        "type", "greeting",
        "target", "lands",
    )
}

プロフィール

レポジトリ: GitHub

ドキュメント: pkg.go.dev

最初のコミット: 2016年8月16日

執筆時点での最終リリース: 2021年12月13日

Kubernetesなどのプロジェクトにコントリビュートしており、執筆現在Googleに在籍しているTim Hockin氏によって作られた実装中立の、ロギングのインターフェイスを規定するライブラリです。実際にログを出力するためには、提供されているバックエンドの実装を通じて logr.Logger を生成して利用することになります。 (2021/12/15追記:コメント欄により純粋なインターフェイス型ではない旨をご教示いただきましたので、文言を修正しました。)

ログのセマンティクスはglogを強く反映したものになっており、ログの深刻度と詳細度を伴ってログエントリーを出力するというものになっています。ですが、このためにバックエンドとのインピーダンスマッチングが必要となっており、ポリシーががバックエンドごとにまちまちなのもあり、ログレベルベースのバックエンド実装との利用には多少の使いづらさがあります。自作のライブラリの中でロギングを行いたく、glogのセマンティクスが好きであれば、このライブラリを使うべきでしょう。

良いところ・特徴

  • ロギングライブラリの実装に対して中立なインターフェイスを使って構造化ロギングが可能。

良くないところ

  • バックエンドがログレベル付きのロギングに対応していても、ライブラリに強い思想が反映されているためマッピングを考慮しなければならない。

まとめ

特に強い思想がなければklogかZap以降のロギングライブラリを選んでおくのがよろしいかと思います。個人的にはRipZapを最近は使っています。

*1:out-of-band data=帯域外データ、主題となる情報とは別に付加的に与えられる情報のこと

*2:筆者が知らないだけです。

無効値の話①

moriyoshi.hatenablog.com

先日このような駄エントリを書いた。

十分ユニットテストがあればきっと防げたであろう問題であるが、それよりも、

なぜnilが必要だったのか

という点で疑問を感じるコメントが散見されたので、その点を補っておきたい。

このプロジェクトではGORMというORマッパー的なものを利用しており、このマッパーを使う限りにおいては、モデルの中でSQL null (NULL) が与えられうるカラムに対応するフィールドは sql.NullString を用いるか値型をそのポインタ型にする必要がある。

type User struct {
    Id int
    Name sql.NullString
}

もしくは

type User struct {
    Id int
    Name *string
}

どちらを採用すべきかという点では議論がある。型のセマンティクスという観点では、SQLの文字列型は母言語の文字列型とは意味論的に違いがあるものなので、前者のように専用の型をあてがうのが妥当と言える。一方で、ORマッパーというからには、データストアの詳細ができるだけモデルに露出しないほうが望ましいという考え方がある。件のプログラムは、後者の観点で、ポインタを使って基本型の値型の NULL を表現していたのである。

encoding/jsonJSON のオブジェクトと struct で表現されたモデルを対応付けする場合にも同じような問題がある。

nullが来ないバージョン:

package main

import (
    "fmt"
    "encoding/json"
    "bytes"
)

type User struct {
    Id int `json:"id"`
    Name string `json:"name"`
}

const jsonStr = `
{
  "users": [
    {
      "id": 1,
      "name": "foo"
    }
  ]
}`

func main() {
    r := bytes.NewReader([]byte(jsonStr))
    val := struct {
        Users []User `json:"users"`
    }{} 
    err := json.NewDecoder(r).Decode(&val)
    if err != nil {
        panic("oops")
    }
    fmt.Printf("%v\n", val)  
}

https://play.golang.org/p/gVayB9HDinj

nullを許容するバージョン:

package main

import (
    "fmt"
    "encoding/json"
    "bytes"
)

type User struct {
    Id int `json:"id"`
    *Name string `json:"name"`
}

const jsonStr = `
{
  "users": [
    {
      "id": 1,
      "name": "foo"
    },
    {
      "id": 1,
      "name": null
    }
  ]
}`

func main() {
    r := bytes.NewReader([]byte(jsonStr))
    val := struct {
        Users []User `json:"users"`
    }{} 
    err := json.NewDecoder(r).Decode(&val)
    if err != nil {
        panic("oops")
    }
    fmt.Printf("%s\n", *val.Users[0].Name)
}

https://play.golang.org/p/bcKXLM8UoN1

encoding/jsonのマーシャリングでも、JSONの文字列型を表現する専用の型を用意してあてがうことは可能だ。しかし、それをしなくても、上記のように値型のポインタを置いておくことでJSON nullに対応付けることもできる。

さて、これまではあくまで母言語と他方言語の双方に、組み込みの値システム / 型システムにおいて、無効値に相当するものが定義されていた場合に、どう対応付けを行うかという視点で考えてきた。

しかし、アプリケーションの設計という意味では、また別の観点もある。SQLであろうとJSONであろうと、母言語のデータ構造との1-to-1マッピングを前提とするならば、そもそもセマンティクス上の不整合が出るようなスキーマ設計をしないということものだ。具体的に言えば、SQLであればNOT NULL制約を付加すべきで、JSONであれば、null値が来るような仕様にしないといった具合である。

無効値と一口に言っても、無効であることが使い手によって明示された結果としての無効値であるのか、実行環境において、何らかの導出の結果として生じた「値が得られない」という事象を指し示す表示としての無効値なのか、の区別があり、特にSQLに関していえば、外部結合などで現れることからわかるように、NULL は後者の意味合いが強い。一方JSONに関しては、それが由来した言語であるJavaScriptのセマンティクスを見る必要があるが、JavaScriptは動的型付け言語で、そこでは複合型 (arrayobject) における要素型に前提を置いていないことにより、ある要素が取りうる値域を複数の型で多重化することが可能なため、null 自体はobject型の無効値であるにもかかわらず、使い手が汎用的に無効値を表す指標として利用可能である一方、object型の操作で後者を表現するものとして undefined という特別な組み込み型が用意されていることから、JSONにおけるnullの役割は、前者を示唆するものとなっている。

Goに立ち返ってみると、静的型付け言語であるGoにおいてはnilは値域として無効値の存在を許されたそれぞれの型 (スライス型、ポインタ型、interface型) ごとに存在するものとして位置づけられている *1

このように、他方言語として取り上げている2つに関してだけでも、何も対処をせずに不整合を避けることはできず、そのような観点にも一理あるといえる。

(たぶん続く)

*1:ただし、異なるinterface型や異なるポインタ型同士の関係演算は定義されていて、異なるnil同士の同値関係が成立する。また、JavaScriptのnull定数と違い、定数としてのnilは型を持たず、文脈によって型が決まるようになっている

nilが欲しいからと言ってむやみにポインタを使うとひどい目にあう話

スマートフォンアプリ側の実装担当として少し関わっているあるβ版のサービスで、奇妙だが比較的クリティカルな問題が発生していた。

それもメッセージが関係ない人間に届くというものであった。

なんとなくその問題を担当することになったが、常に状況が再現するわけではなく、他の仕事もあったので、問題への見当を付けられないまましばらく過ごしてしまった。

そのメッセージを送信する部分はサーバサイドのコードで、Goで書かれていた。

そのコードのエッセンスを抽出すると、以下のようになる。

package main

import (
    "fmt"
    "sync"
)

type User struct {
    Id   int
    Name string
}

type Mail struct {
    Title string
    UserId *int
}

func sendMail(mail Mail, wg *sync.WaitGroup) {
    fmt.Printf("Title=%s, UserId=%d\n", mail.Title, *mail.UserId)
    wg.Done()
}

func main() {
    users := []User{
        User{Id: 1, Name: "AAA"},
        User{Id: 2, Name: "BBB"},
    }

    wg := &sync.WaitGroup {}
    for _, user := range users {
        mail := Mail{
            Title: fmt.Sprintf("%s, check out our season offerings!", user.Name),
            UserId: &user.Id,
        }
        wg.Add(1)
        go sendMail(mail, wg)
    }
    wg.Wait()
}

The Go Playground

sendMail() に渡される引数であるところの Mail の値はループの中で都度作られているので一見よさそうに思えるのだが、実行してみると、時として次のような結果になるのだ。

Title=BBB, check out our season offerings!, UserId=2
Title=AAA, check out our season offerings!, UserId=2

(Goroutineのyieldするタイミングによって結果が変わるので、期待値通りになることもある。)

もちろん、期待値は

Title=BBB, check out our season offerings!, UserId=2
Title=AAA, check out our season offerings!, UserId=1

のように、タイトルに含まれるユーザ名とユーザのidが一致することである。

あな恐ろしや…!!!

原因は、 MailUserId として、ループ外のスコープで定義された userId メンバへのポインタが与えられ続けるためだ。

「ループ外」と書くと、「userはfor文より外のスコープで扱えないわけだからループの中だろ」というツッコミが入りそうだが、実際のスコープの内実はこうだ。

  • for文の外側のスコープ
    • for文の宣言のスコープ (for ... := ... の部分)
      • for文の内側のスコープ ({ } の中)

この中間のスコープはブレース (中括弧) で囲まれていない範囲なので意識しづらいのだ。

さて、このコードは取り急ぎ以下のように書き換えればよい。

package main

import (
    "fmt"
    "sync"
)

type User struct {
    Id   int
    Name string
}

type Mail struct {
    Title string
    UserId *int
}

func sendMail(mail Mail, wg *sync.WaitGroup) {
    fmt.Printf("Title=%s, UserId=%d\n", mail.Title, *mail.UserId)
    wg.Done()
}

func main() {
    users := []User{
        User{Id: 1, Name: "AAA"},
        User{Id: 2, Name: "BBB"},
    }

    wg := &sync.WaitGroup {}
    for _, user := range users {
        userId = user.Id
        mail := Mail{
            Title: fmt.Sprintf("%s, check out our season offerings!", user.Name),
            UserId:  &userId,
        }
        wg.Add(1)
        go sendMail(mail, wg)
    }
    wg.Wait()
}

The Go Playground

書き換えればよい、とは書いたものの、こういうコードにすべきじゃないというのが正直なところだろうか。

「ユニコード」で予期せぬ目に遭った話

などというツイートをしたところ、思ったより反響があったのでまとめておく。

上記ではあいまいに「バリエーション」などと書いたが、Unicodeとそれを扱う環境においては、バリエーションと一口に言っても次のような状況がある。

  1. 意味論的に等価な異なる字形の集合
  2. 同じ字形で異なるコードポイントの集合

aは結構なじみ深いと思う。

a-1. 異なるコードポイントにそれぞれ異なる字形が割り当てられているもの

例:

  • 「東」(U+6771) ⇔「东」(U+4E1C)
  • 「斉」(U+6589) ⇔「齊」(U+9F4A)
  • 「高」(U+9AD8) ⇔「髙」(U+9AD9)

a-2. 同じコードポイントで、フォントによって字形が異なるもの

例:

  • MS MinchoのU+9AA8」(MS MinchoのU+9AA8) ⇔「SimSunのU+9AA8」 (SimSunのU+9AA8)
  • EmojiOneのU+1F600」(EmojiOneのU+1F600) ⇔「NotoのU+1F600」 (Noto Color EmojiのU+1F600)

a-3. 同じコードポイントで、異体字セレクタなどによって字形が特定されるもの

例:

  • EmojiOneのU+260E」(U+260E + VS16)⇔「MS MinchoのU+260e」(U+260E + VS15)
  • 「辻󠄁」(二点しんにょう U+8FBB + VS18) ⇔「辻󠄀」(一点しんにょう U+8FBB + VS17)

bの状況としては、

b-1. 意味論的にも同じだが政治的・歴史的経緯で重複して収録されているもの

例:

  • 「A」(全角アルファベットのA、FULLWIDTH LATIN CAPITAL LETTER A U+FF21)⇔「A」(アルファベットのA、LATIN CAPITAL LETTER A U+0041)
  • 「א」(ヘブライ文字アレフ U+05D0)⇔「ℵ」(アレフシンボル U+2135) *1

b-2. 意味論的に異なっているため包摂されず別個に収録されているもの

例:

  • 「西」 (WEST U+897F) ⇔「⻄」(CJK RADICAL WEST TWO U+2EC4)

さて、ツイートしたのは、b-2 の状況である。CJK Radicalsとは「部首」を表す文字のことで、意味論的には単一の部首のみで構成されるCJK Ideographとは区別される。

これの何が恐ろしかったかというと、現実に (とあるインターネットサービス上で) ユーザーが住所の一部に入力した文字としてこのCJK Radicalsが出現し、CP932に変換できないという事案が発生したからだ。

JISX0208とJISX0213で例示字形が異なることからWindowsのバージョン間でもフォントの差異があり、しばしばやり玉に上げられる「辻」などでも、最近のOS標準のIMEがIVSにも対応していることから、同様の問題が起こりそうな予感がする。やれやれ。


*1 両者が意味論的に等価かどうか、というのは議論の余地がある、たとえば「R」と「ℝ」は文脈の区別をしたいからこそ字形が異なっているわけなので。しかし、ここではdecomposed formがあるかないかを基準とすることにした。

mod_wozozo

(この記事は、Pyspaアドベントカレンダー 2016の12/4のコミットを補足する形で書かれました。)

はじめに

皆様ご存知のことと思いますが、OSSコミュニティーにおいて、開発者が結婚する際には、新郎と新婦に

オリジナル○○○○○○○○○○○

を贈呈するという慣習があります。

はい、もちろん

オリジナルApacheモジュール

ですね。

タイムライン

10/3

ハンドルwozozoだしやっぱりOzネタで行くしかないだろうということで、OzのApacheモジュールを実装することにする。

12/4

11:00

起床。全日の京都での披露宴参加からの帰宅で思いのほか疲れており、8時起床予定が大幅にずれる。

11:30

鬼平犯科帳スペシャルを見始める

13:40

鬼平犯科帳スペシャルを見終わる。そろそろアドベントカレンダーのネタ仕込みするかと思い、github.com:mozart/mozart2 をチェックアウト

13:45

ビルドインストラクションを見る。とりま cmake などを入れてみて、 cmake . などする。

13:50

cmake が通らない。自動的に clang とか LLVM とか落としてくると書いてあるのだが... 仕方なく OS (Ubuntu 15.04) のパッケージから LLVM を入れてビルドを試みることに。

14:00

OS のパッケージの clang や LLVM では、なぜかインストールされるファイルの欠損がありビルドができない。Ubuntu 16.10 では直っているようなので、do-release-upgrade を試みる。

14:20

OS のアップグレードが完了したので、ビルドを開始する。

14:30

ビルドに失敗するので、いろいろ調べてみると、ライブラリ付属の cmake ファイルの甘さがいくらかあることが判明。どのオプションが必須なのかを調査する。

14:40

オプションの指定を解明できた。ビルドが走り始める。時間がかかりそうなので、食事に出かける。

15:00

食事から戻る。ビルドは無事完了していた。ランタイムのテストをするため、Oz の言語仕様などを調べ始める。

15:15

古いバージョン (Mozart1) の資料からコピペしてサンプルコードを動かすことに成功。

15:30

標準出力に出力する方法 (System.show) などを学ぶ。

16:00

ソースコードの構成を学びはじめる。

17:00

VMのフロントエンドとしてBoostにプラットフォームの差異を吸収させたboosthost と、それの対になる boostenv というコンポーネントがあることがわかる。この部分で切り出すことでApacheモジュールに組み込めそうだという見込みを立てる。

17:10

Apacheモジュールのひな形を書き始める。apxsはそのまま使えないのでapxsから変数だけクエリしてあとはMakefileでやることにする。

18:30

催促される。

19:00

libtool に -module オプションを渡しても .so が生成できない問題の謎が解ける。 (-rpath オプションが必要だった)

19:30

ひな形にMozart2のコードの一部を組み込んだ形でコンパイルを通すことに成功する。

だが、Mozart2のビルドシステムでビルドされるコンビニエンスライブラリ (最終的なバイナリ生成物である ozemulator を生成するためにビルドの途中で便宜的に作られるライブラリ) は、PIC コードではなかったのでリンクで失敗してしまう。

仕方ないので CMAKE_CXX_FLAGS-fPIC を追加した形で Mozart2 をビルドしなおすことに。ビルドに時間がかかるので食事に出かける。

20:00

食事から戻り、作業再開。すぐにビルドには成功する。

Apacheのconfigから得られた内容をVMの起動パラメータに変換する簡単なお仕事の開始。

21:00

I/Oスレッドの扱いに悩み始める。I/Oスレッドをひとまずpost_configフェーズで起動する形で実装。

22:00

handlerVMを起動させるところまで来る、が、VMが起動しない。デバッグを続ける。

23:40

ドはまりしたが、余計なパラメータを渡していることが原因と判明、修正し、リクエストURIで指定されたドキュメントルート配下のMozart2のバイナリを読み込んで実行することに成功する。しかし、この時点では、まだレスポンスを書き出すことはできていないので、標準エラー出力への実行結果の出力で確かめるのみ。

24:00

Apacheとのつなぎこみを始める。最初の難関である、VMの起動時にVMにrequest_recを渡すという部分への対応を開始する。

25:20

VMのパラメータとして渡しているのは、値渡しのVMIdentifier VirtualMachineOptions型と、 std::unique_ptr<std::string> 渡しのアプリケーションURLのみ。

std::string を継承したクラスを作り、そこに request_rec を突っ込むという強引なやり方で成功する。

25:30

Mozart2 のビルトインプロシージャの作り方を調べる。C++のクラスの実装と、それをビルドシステムのブートストラップでclangのAPIを使ってパースしてスタブを生成するコードから成ることを解明して、スタブを自前で書くことで対応を開始する。

26:00

レスポンスを書き出すビルトインプロシージャを作るには、VM生成時に渡されたrequest_recをプロシージャの文脈で取得できなければならないが、しかし、エントリポイントは、スタティックメソッドである。

VMからビルトインモジュール名を指定してモジュールを取得できそうなことが分かったので、その方法を調べる。

27:10

vm/vm/main 配下のVM内部の実装を読み解き、ようやくモジュールを取得してもコンテキストは取れないので、代わりにビルトインプロシージャのスタブそのものへのポインタを取得する方法しかないことが判明する。

27:40

Apache.Rputs の実装ができ、ブラウザに文字を出力することに成功する。疲弊しきったため風呂に入る。

28:00

1時間ほどの仮眠を試みるが、4時間寝てしまう。

32:00

Ozで何をするかを決めようとする。I/Oスレッドが独立していることから、それが正しく動いていることを確認するためのコードを書きたく、それをそのままネタにすることにする。

32:10

TCPでの通信の方法を調べはじめる。とりあえずApacheの文脈から外れて、Ozでスタンドアロンで通信をするコードを書く。サーバー側はGoで実装した。

33:10

Goで実装したサーバーとの通信に成功する。

33:20

通信した内容をApacheを通じてレスポンスとして返すことに成功する。 ネタを仕込むための実装を始めるため、Ozの標準モジュールについていろいろ調べ始める。

33:40

ちょっとした遊びを実装するため、Apache.Rflush の実装をする。

34:10

通して動くようになる。レポジトリを作成して、push。

34:54

最後に

めでたい。

FFmpegで動画編集をするガイド

こんにちは。年末になり、ますますコマンドラインで動画編集をする機会が増えてきているかと思いますが、皆様いかがお過ごしでしょうか。普段触れていないとついつい忘れてしまうffmpegのオプション群。そんなあなたのためのチートシートです。

基礎編

トランスコーディング

ffmpeg -i input.mp4 -c:v libx264 -preset medium -c:a libfdk_aac output.mp4

または

ffmpeg -i input.mp4 -vcodec libx264 -preset medium -acodec libfdk_aac output.mp4

解説

-c:v オプションは映像コーデックを、-c:a は音声コーデックを指定する。古くはそれぞれ -vcodec -acodec というオプションであった。両者は等価である。

-preset は libx264 の設定プリセット名を与える。

AAC エンコーダは ffmpeg ネイティブのものもあるが (aac) 2015年12月現在、未だ実験的 (experimental) な扱いとなっているため、libfdk_aac を代わりに使っている。なお、デコーダは experimental ではない。

(もしネイティブの aac コーデックを利用する場合には -strict experimental オプションが追加で必要となるので注意)

コンテナフォーマットの変更

ffmpeg -i input.flv -c:v copy -c:a copy output.mp4

または

ffmpeg -i input.flv -c:v copy -c:a copy -f mp4 output.mp4

解説

出力ファイルフォーマットは拡張子から自動的に決定される。-f オプションにより明示することもできる。コーデック copy を指定すると、入力ストリームはエンコード・デコードを経ずにそのまま出力に流される。

映像から音声を抜き出す

ffmpeg -i input.mp4 -c:a copy -vn output.mp4

または

ffmpeg -i input.mp4 -c:a copy -map 0:a output.mp4

解説

コンテナフォーマットに依存するが、基本的には動画ファイルは1つ以上の映像ストリームと音声ストリームから構成されている。何も指示がない場合、ffmpeg は入力のストリームの構成から自動的に出力のストリームの構成を決定する。入力ストリームと出力ストリームの対応を明示的に行うには -map オプションを用いる。-map オプションを指定した場合、対応づけが行われていないストリームは破棄される。

-map オプションに指定できるのは次のような識別子である。

識別子 説明
0:0
1:1
0番目の入力ファイルの0番目のストリーム
1番目の入力ファイルの1番目のストリーム
0:v
1:a
0番目の入力ファイルの全ての映像ストリーム (出現順)
1番目の入力ファイルの全ての音声ストリーム (出現順)
[out] libavfilter (lavf)のストリーム名 (後述)

動画に別録りした音声をつける

ffmpeg -i input.mp4 -i audio.mp3 -c:v copy -c:a aac -strict experimental -map 0:v -map 1:a output.mp4

解説

ffmpeg では -i オプションを繰り返し指定することで、複数の入力ファイルを指定できる。最初の -i オプションで指定したファイルは 0 番目のファイル、次の -i オプションで指定したファイルは 1 番目のファイルとなる。

この例では、前述の -map オプションを用いて、input.mp4 ファイルの動画ストリームと audio.mp3 の音声ストリームを合わせて output.mp4 として出力している。

動画のリサイズ

ffmpeg -i input.mp4 -s hd480 output.mp4

または

ffmpeg -i input.mp4 -s 852x400 output.mp4

または

ffmpeg -i input.mp4 -vf scale=hd480 output.mp4

または

ffmpeg -i input.mp4 -vf scale=852:400 output.mp4

解説

-s オプションは出力される動画ストリームのフレームサイズを指定する。一方、-vf オプションは動画ストリームに適用するフィルタを設定する。

明示的な指定がなくとも、常に暗黙にスケーリングフィルタが適用されるので、-s オプションの指定で大体は十分ではあるが、スケーリングフィルタを明示的に指定することで、細かな設定が可能になる。

(実は上の例で-vfオプションを指定した場合には明示的に指定されたフィルタの上に等倍のスケーリングフィルタが適用されることになり、二重にスケーリングフィルタが適用されることになるが、問題になることはない)

動画から連番のPNGファイルを生成

ffmpeg -i movie.mp4 -c:v png -f image2 output/%06d.png

解説

出力フォーマット image2 では %XXd のようなプレイスホルダーをファイル名に含めることで、フレーム番号をファイル名に含めることが可能である。

動画からアニメーションGIFを生成 (thanks to Yoshiori)

ffmpeg -i movie.mp4 -c:v gif -f gif -r 8 -s 320x180 output.gif

解説

出力フォーマット gif を使うとアニメーションGIFを生成することができる。元動画のフレームレートが高い場合、出力ファイルサイズが肥大してしまうかもしれない。そのような場合は -r オプションを指定することで、出力ファイルのフレームレートを指定して、調整を図る。

動画の特定の範囲を切り出す

ffmpeg -i movie.mp4 -ss 10 -t 20 -c:v copy -c:a copy output.mp4

解説

-ss オプションを指定すると、続く引数に指定された秒数にシークして変換を開始する。-t オプションは、続く引数に指定された秒数、変換を行う。

応用編

動画に画像を重ねる

ffmpeg -i movie.mp4 -i picture.png -filter_complex '[0:0] [1:0] overlay=x=0:y=0 [out]' -map '[out]' -map 0:a output.mp4

解説

overlayフィルタを利用すると、フィルタの0番目の入力を1番目の入力に重ねることができる。

この例では、最初の -i オプションで指定された映像のストリーム ([0:0]) をフィルタの0番目の入力に、次の -i オプションで指定された映像のストリーム ([1:0]) をフィルタの1番目の入力として、1番目の入力を0番目の入力のフレーム上の座標 (x, y) = (0, 0) に重ねている。

指定したタイミングで映像に画像を重ねる

ffmpeg -i movie.mp4 -i picture.png -filter_complex '[0:0] [1:0] overlay=x=if(gt(t,5),if(lt(t,10),0,-10000),-10000),y=0 [out]' -map '[out]' -map 0:a output.mp4

解説

overlayフィルタのパラメータにはexpressionを使うことができる。この例では現フレームの時間であるtという変数を使ってオーバーレイする座標を非連続に設定している。

5秒未満: x=-10000 10秒未満: x=0 10秒以上: x=-10000

重ねる対象を x=-10000 のように画面外に持ってくることによって特定のタイミングで重ね合わせを行うことを実現している。

まとめ

とくにまとめるような内容ではないのですが、よいお年をお迎えください。

Many thanks to pyspa community.

この記事はPyspa Advent Calendar 2015のエントリとして書かれました。次の記事はこちらです。

識別子に絵文字などを使えるようにする

とある言語で識別子に絵文字などのシンボルが使えるそうなのですが、一応GoだってUnicodeクリーンなんだ。

f:id:moriyoshi:20140603121552p:plain

これをコンパイラに食わせてみる。

$ go run sushi.go

どうだ?

# command-line-arguments
./sushi.go:3: invalid identifier character U+1f363
./sushi.go:8: invalid identifier character U+1f363

なのでちょっと悔しい。ということでやりました。


$ go run sushi.go
sushi~