Goならわかるシステムプログラミング第2版が出たので書評しますね

少し前になりますが、3月23日に、渋川よしきさんの著された「Goならわかるシステムプログラミング 第2版 」が発売されました。初版と比べてかなり加筆されておりパワーアップしているので、初版をすでにお持ちの方でもさらに興味深く読むことのできる内容に仕上がっている、というのが第一印象です。

残念ながら初版発売時に記事にする機会がなかったのですが、あらためて今回書評したいなと思いましたので、徒然書いていきたいと思います。

この本は実はシステムプログラミングの本ではないかもしれない

システムプログラミング」とは何でしょう。正直私にもわかりません。その語をはじめに思い浮かべた人は、プログラミングという概念のその中にあえて「システムプログラミング」という分類を作ろうと思い至ったということですから、きっと「非システムプログラミング」というものもあるということでしょう。知らんけど。しかし、これは本書の位置づけを議論する上で重要な視点となります。

書評する立場ながら大変申し訳ないことに見識もないもので、ついWikipediaを見てしまうわけですが、探してみると「Systems programming」という記事が見つかりました。これが最初に作られたのは2003年とのことなので、ある程度信頼を持って眺めても良さそうではあります。当該記事の冒頭から引用してみます。

Systems programming, or system programming, is the activity of programming computer system software. The primary distinguishing characteristic of systems programming when compared to application programming is that application programming aims to produce software which provides services to the user directly (e.g. word processor), whereas systems programming aims to produce software and software platforms which provide services to other software, are performance constrained, or both (e.g. operating systems, computational science applications, game engines, industrial automation, and software as a service applications).

この記事によれば、「アプリケーションプログラミング」という概念があり、「システムプログラミング」との違いは「アプリケーションプログラミングはユーザーに直接サービスを提供するものである一方、システムプログラミングはその他のアプリケーションにサービスを提供するものである」とのことです。なるほど、「非システムプログラミング」というのは「アプリケーションプログラミング」のことなのかもしれない。そうすると、システムプログラミングはオペレーティングシステム自体、またはそれに関わるもののプログラミングという言い方が暫定的にはできるかもしれない。

システムプログラミング言語とは?

ところで、「システムプログラミング言語」という言い方もあります。これはこれで独立した記事「Systems programming language」が存在するのでそちらも眺めてみることにしましょう。

A system programming language is a programming language used for system programming; such languages are designed for writing system software, which usually requires different development approaches when compared with application software. Edsger Dijkstra refers to these language as Machine Oriented High Order Languages, or mohol.

システムプログラミング言語というのは、アプリケーションソフトウェアを開発するのとは異なるアプローチが要求されるシステムソフトウェアを記述するのに適した言語である」と述べています。そして、そのような言語をエドガー・ダイクストラは「機械志向高階言語」と呼んだと述べています。(参考: https://www.dijkstrascry.com/node/121 )

果たして「Machine Oriented High Order Languages」(MOHOL) という呼称を思いついたのがダイクストラであったのかどうかは不明ですが、当該記事によればこの呼称は1973年に北オランダで開催されたIFIP working conferenceのダイジェスト [1] に登場するようです。Software: Practice and ExperienceのVolume 7, Issue 1 (1977) に掲載されたS. H. Valentineによる当該ダイジェストの書評を引用します。なお、時代背景の理解を助けるために記すと、Cが生まれたのは1972年といわれています。

Machine Oriented Higher Level Languages turned out to be a slightly contentious title. There was a good deal of discussion about the nature of Machine Oriented Languages (MOL’s) and their relationship to System Implementation Languages (SIL’s). Some of the desirable features of the latter were identified, such as high implementation efficiency and the ability to manipulate complicated data structures. It was admitted that these features may be of interest in other programming contexts as well, and several of the proposals for SIL design throughout the book included features which would be of general applicability. System implementors, however, are perhaps as a group more willing than others to learn a new programming language to achieve their aims. They may also in the near future be the only group who are prepared to accept any machine-dependency at all.

There seemed to be general agreement that assembly languages should be abandoned, and it appears that the manufacturers share this view. There were clear disagreements on what should replace them. A paper by Barreveld describes ALIAS, a machine-independent language intended for minicomputers, with a high-level syntax but low-level semantics, with no typing of data and an explicit dereferencing operator inspired by BLISS. Other language designers have gone for fully typed semantics. These tend to be influenced by existing high-level languages like Algol 68 and PASCAL. A paper by Conradi and Holager makes a study of MARY, a language of this class, on the question of the typing of data. There were some sharp disagreements expressed on this issue in the final panel discussion.

この一文は本書に立ち返っても非常に貴重な洞察を与えます。引用の抄訳を順に記します。

まず最初の段落ですが、

機械志向高水準言語 (Machine Oriented Higher Level Languages) というのは、いささか議論を呼ぶ表題であった。 MOL (機械志向言語) の性質と、それらのSIL (システム実装言語) との関係性については、これまでさまざまな議論があった。だが、後者の望ましい特徴というのはいくつか判明している。たとえば、複雑なデータ構造を操作する効率や能力といったものである。このような特徴はプログラミングにおける他の側面でも重視されうるものであり、原著を通して述べられたSILの設計に関する提案の中にも、より広範に適用可能なものがある。集団としてのシステムプログラマ (システム実装者) は、自らの目的のために、他 (の実装者) と比べて新しいプログラミング言語を学ぶことに積極的であるといえよう。また、システムプログラマは、近い将来機械依存性を許容しうる唯一の集団となるかもしれない。

MOLこそがシステムプログラミング言語を指した語であるのかと思いきや、「システム実装言語」という言葉が出てきます。システム実装言語を文字通り解釈すればシステムプログラミング言語となるので、少し混乱してきました。SILの正体が何であるかは別として、MOLとの違いは「複雑なデータ構造を操作する力」であるようです。操作できるというからには、それに対応する記述力が備わっていると推測しても大きく間違っていないでしょうから、「複雑なデータ構造を記述する力」と言い換えても許されるのではないでしょうか。

この部分、現代からすると「何を言ってるんだ」となりそうなものですが、当時、オペレーティングシステムの複雑さに比べれば、アプリケーションは非常に単純であったという点を考慮しなければならないでしょう。システムプログラミングは相対的に認知負荷が高い行為であり、それを軽減することのできる (高水準な) プログラミング言語があるならばそれを選びたいという動機はシステムプログラマに強くある一方で、本質的にシステムプログラミングはマシンアーキテクチャの詳細にも触れる必要があるものであるということです。

実際、その時代は相反するとも言えるそれらの要件を両立する挑戦として、アカデミックにもソフトウェア産業としても盛んに実験が行われていたのです。2002年にSoftware: Practice and Experienceに掲載されたThe BLISS programming language: a history.という記事 [2] には、次のような記述があります。

In the late 1960s and early 1970s, the use of high-level languages for systems programming was highly controversial. Most systems had very limited amounts of main memory; indeed, even so-called large systems generally had hardware maximum address space limitations of 16 or 18-bits of addressable memory—and no virtual memory support either. ‘Size is the goal’ for both code and data often summarized one side of the debate. Systems programmers wanted lots of control over every instruction and every cycle and every bit of memory used. The advocates for using high-level languages cited the potential for improved productivity and reduced error rates through the use of structured programming and data abstraction. However, the languages that seemed expressive enough for the job at the time, languages such as PL/I or Algol 68, were not viewed as suitably efficient. Arguments raged over whether it was even conceivable, let alone practical, for compilers to produce code that was within some small incremental percentage of what could be achieved by good programmers. No one ever picked zero. Lots of experimentation was in progress throughout the computer industry seeking languages with the right blend of high-level features, low-level control, ease of compiling to efficient code, and improved optimization technology. The few, then contemporary, languages that fit these goals according to the earliest paper on BLISS were EPL (‘Early PL/I’, a bootstrapping PL/I subset used for Multics), Burroughs Extended Algol, PL360 and BCPL.

訳:

1960年代後半から1970年代前半にかけて、システムプログラミングに高水準言語を採用することは、かなり否定的にとらえられていました。多くのシステムは非常に限られたメインメモリしか備えておらず、大型システムと言われるものでも、16ビットから18ビットのアドレス空間のメモリしか扱えないハードウェアから成っており、仮想メモリのサポートもありませんでした。当時の議論の半分はコードにしてもデータにしても「サイズこそがゴール」という言葉に尽きます。 他方、高水準言語を推す側は、構造化プログラミングやデータ抽象化を通じて高い生産性とより低いバグ発生率を達成できる余地があることを強調していました。しかし、当時システムプログラミングにおいてそのような言語にも十分表現力があると考えられていたにもかかわらず、PL/IやAlgol 68といった言語は目的に照らして効率的とは考えられていませんでした。議論は白熱し、実用的かどうかの範疇を超えて、果たしてどの程度、コンパイラの生成するコードが、腕のたつプログラマーの書く (アセンブリ言語の) コードに肉薄できるか、というところにまで至りました。しかし誰一人違いをゼロとは言いませんでした。 高水準言語の特徴、低水準言語の取り回しの良さ、効率的なコード生成の容易さ、より進んだ最適化技術がバランスよく混ざった言語を探す試みがコンピュータ業界全体で行われていました。その中でも数少ない、現代にも残る言語の中で、BLISSの初期の論文にその目的を満たすものと述べられているものはEPL (「Early PL/I」という、Multicsのブートストラップに用いられたPL/Iのサブセット言語) と、バローズ社の拡張Algol、PL360、それからBCPLでした。

最初のMOLとSILの対比が何を意味するのかについての答えは、この部分の参照にあるように、前者が低水準言語、後者が高水準言語、というように考えてよさそうです。MOとHLの両方の性質を兼ね備えた、この議論の時点ではまだ存在していなかったMOHLを模索していたということです。

さて、一旦もとの文章に戻ります。

アセンブリ言語はいずれ放棄されるべきである、という見解については広く合意があるように思われたし、また、(計算機) メーカーもそれを支持しているようだが、一方で何でもって置き換えるべきかという点では明らかな意見の相違がある。Barreveldの論文のALIASは、BLISSの影響を受け、型なしデータと明示的なデリファレンス演算子を持つという、高水準の文法と低水準のセマンティクスを兼ね備えた、ミニコンピュータ向けの機械非依存言語である。他の言語設計者は完全に型付けされたセマンティクスを好んでいた。そのような言語にはAlgol 68やPASCALといった既存の高水準言語に影響されたものが多い。ConradiとHolagarの論文は、この種のMARYという言語について、データの型づけの有効性を検討するものである。この問題については最後のパネルディスカッションでかなり明確な意見の食い違いが見られた。

BLISS は1969年にカーネギーメロン大学で開発され、一時はベル研究所でCとシステムプログラミング言語の座を争ったという経緯のある言語ですが、この言語は型という型のバリエーションを持たず、すべての変数も定数もアーキテクチャ依存のフルワードの整数値 (例えばPDP-11をターゲットとするならば16ビット、PDP-10をターゲットとするならば36ビット) を格納するという仕様でした。また、これは当時のミニコンピュータの主流アーキテクチャに由来すると思われるのですが、すべての変数は何らかのメモリ空間上のアドレスに対応しており、変数の表す値はその値ではなくアドレスというセマンティクスを採用していました。そのため、変数の値を取り出したり、値を格納する際 (デリファレンス) には . 記号を変数の前に置く必要があります。高水準の文法といえども、セマンティクスは非常に原始的で、かつアーキテクチャ依存であり、これが生産性の高い言語と考えられていたということは非常に興味深い点です。

そのような背景があるため、Algol 68やPASCALといった系譜に属する型付けを持つ高階言語が当時システムプログラミングの分野で花開くことはありませんでした。そのため、1980年にAdaという形でアメリカの軍事規格に採用されたことは、当時のコンピュータ業界に大きな驚きをもって迎えられることになります。どのくらい議論を呼んだのかというと、トニー・ホーア *1チューリング賞の記念講演で名指しで信頼性について疑問を呈する発言をするほどでした [3]。宇宙開発や軍事産業などの分野で複雑な機械制御のためにコンピュータが組み込みという形でその適用の場を広げることになると、現在のようにフラッシュメモリを搭載することでファームウェアをインサーキットプログラミングするというような概念がない中で *2 製造時点でのコードから一切変更できない組み込み分野でいかに品質を高めるかということが課題となりました。アメリカ国防総省は当時450種類もの (多くはアーキテクチャ依存で、アーキテクチャ保全が終了した時点で放棄された) 言語が兵器の制御に用いられていることを憂慮し、1975年にHigh Order Language Working Group (高階言語ワーキンググループ) を結成し、それらにとって代わる新しい言語の模索を始めました。もともと彼ら彼女らは既存の言語の採用を検討していましたが、最終的に要件を満たすものがないと判断し、新規に言語の開発を行うことを決断します。その結果誕生したのがAdaでした。Adaのような高階言語が「ビジネス」になったということがそうした言語の研究開発を促し、(この文脈にはSmalltalkなどの動的型付きオブジェクト指向言語が含まれます) 最終的にJavaのようなガベージコレクションをランタイムに備えた汎用プログラミング言語の開発につながったのではないかと、個人的には思います。

そしてGo

1977年という時代を考えると、ここでCについての言及が少しもないのは不思議に思われたかもしれません。それはというもの、Cは1978年にブライアン・カーニハンとデニス・リッチーによる書籍が出版されるまではずっとベル研究所のインハウスプロジェクトであり、様々なソフトウェアプロジェクトで使われたといえども、そこで成熟されてきたインハウスプログラミング言語であったということです。GoがGoogleのインハウスプロジェクトであったことを振り返るととても示唆的に思えるところがあります。

これは別の機会に述べたことがあるのですが、Goのソースコードレポジトリの最初のコミットは、実はGoではおろかCでもありません。

github.com

hello, world
R=ken
DELTA=7  (7 added, 0 deleted, 0 changed)

Brian Kernighan committed on Jul 19, 1972

意味深なコミットですが、これはBと呼ばれるC以前にブライアン・カーニハンによって開発された言語によって書かれた Hello World です。Bは既出であるBCPLと呼ばれる言語に強くインスパイアされた言語で、BCPLの持つ特徴であるブレース ({ }) によってブロックを表現する仕様などで影響を受けています。 ((なお、BCPLのコメントは // を前置することで記述できますが、この仕様はCには引き継がれず、C++で復活を遂げることになりました。))

そして次のコミットは

github.com

ですが、これは前コミットでBで書かれた内容をCに書き直したものとなっており、GoがBから始まるベル研究所プログラミング言語のブートストラップの系譜にいるということをまるで示唆するかのようなイースターエッグとなっています。

Goにようやく話が戻ってきたところで、システムプログラミング言語とは、システムプログラミングとは何なのか、という問いに戻ってみたいところですが、歴史を振り返って得られた知見というのは、そこに求められる性質というのは、以下に集約されそうだということです。

  • 抽象的なデータ構造の記述力 (Goでいうstructやinterfaceを含む型システム)
  • 構造化プログラミング (Goでいうスタックフレームに基づく関数スコープ)
  • ハードウェアアーキテクチャに基づいた操作の記述が可能 (Goでいう豊富なプリミティブ型、unsafe)
  • 上記を担保しつつ、コンパイラが高効率なコードを生成できること

それからもう一つ、求められる性質自体は、時代時代の要請によって変化しうるという点です。ここでGoは明らかに上記4つの性質を備えながら、Cにはない以下の特徴を持つことになりました。

これらのうちの多くは、1990年代から2000年代のコンピュータ業界に大きな足跡を残し現在も広く使われるJava、それからPythonをはじめとする多数のスクリプト言語の影響がないとは言えない特徴です。特に、「認知負荷を低減し、高い作業効率が達成できる」という側面は、1960〜70年代と比べ飛躍的に実装面積あたりの計算性能が向上し、同時にコストが低下したことでコモディティ化を達成した高性能な小型計算機の存在を強く反映したものといえます。つまり、低水準と高水準の両立という自転車置き場の議論は計算資源に乏しかった時代の産物であり、ムーアの法則は言うまでもない製造技術の進歩が自然と本来の「システムプログラミング言語」を我々にもたらした、ということです。

小型化、低コスト化した高性能な小型計算機がワークステーションやパーソナルコンピュータという呼称で広く一般にマーケティングされるようになり、システムプログラミングに求められる言語的、ランタイム的要素のあり方を変容させましたが、このことは同時にアプリケーションプログラミングとシステムプログラミングの境界も変化させてきたと個人的に考えています。それが象徴的に現れているのがシェルの実装です。ベル研究所で開発されたBourne Shellの最初のバージョンは1979年でしたが、Korn Shellは1983年、Bashは1989年、Z Shellは1990年と着実に新しい世代が誕生しており、オペレーティングシステムの単なる外層という役割を超えて、システムオペレータの生産性という観点での進化を遂げてきました。その意味で、現代的に「低レベルアクセス」ということは、必ずしもマシンアーキテクチャを直接触ることのできるような過去の意味での低レベルのみを意味せず、抽象化層を経由しないでシステムコールのようなOSのプログラミングインターフェイスに触れることをも低レベルと呼ぶことは、そう大それたことではないといえるのではないか、と思っています。

「Goならわかるシステムプログラミング」はどこに流れ着くか

上で述べたことを一言で言えば、利用可能な計算資源の増加と生産性の追求からシステム全体の複雑性が増し、「低レベル」の枠が広がったことで、そこに含まる概念やトピックも一面的ではなくなってしまった、ということなのですが、その点についていうと、システムプログラミングに関して、何が関心事か、何を知っておかなければならないのか、ということを1冊で横断的に解説するのはとても困難なこととなってしまったように思います。1冊の旅行ガイドで世界旅行を案内するのが無謀であることと同様なようにです。ですから、本書に対してそのような期待を抱くのは、少々筋が違うということになるでしょう。では何であるかというと、著者である渋川よしきさんの、システムプログラミングの世界の探訪記と捉えています。もちろん、訪れたいろいろな地域の詳細はきちんと調査されて、サンプルコードにより裏付けがされている点では、随筆のような旅行記とは異なるのですが。

もし本書を手に取る機会がありましたら、旅行先の歴史や文化の背景を学ぶとより興味深くなるように、コンピュータサイエンスの歴史なども頭に巡らせながら読んでみると、より面白く読めると思います。各章で取り上げる内容について、他の解説も参照し掘り下げながら、理解を深めつつロマンを味わうのも、一般的な技術書にはない楽しみ方かと思っています。

[1] van der Poel, W. L.; Maarssen, L. A., eds. (27–31 August 1973). Machine oriented higher level languages. IFIP Working Conference on Machine Oriented Higher Level Languages (MOHL). DOI: 10.1002/spe.4380070115

[2] Brender, Ronald F. The BLISS programming language: a history. Softw. Pract. Exper. 2002; 32:955–981. DOI: 10.1002/spe.470

[3] Hoare, C. A. R. The Emperor's Old Clothes. Communications of the ACM; Vol. 24 Issue 2. DOI: 10.1145/358549.358561

*1:C.A.R. HoareはGoの並行処理のセマンティクスの礎となっているCSPを発明した人物です。皮肉なことには、Adaの仕様にはCSPの影響を受けたrendezvousと呼ばれるプリミティブが含まれています。なお、この批判についてホーアはのちに謝罪しています。関係ないけどnull参照を発明したことについても謝罪している。えらすぎる。

*2:ちなみにEPROMが発明されたのは1971年です。

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のエントリとして書かれました。次の記事はこちらです。