読者です 読者をやめる 読者になる 読者になる

恥ずかしながら、golangの多値を返す関数の戻り値を引数に渡した場合の挙動を把握していなかった

はじめに

通常の言語だと、多値とdestructuring(分配束縛)は別物で、単一の構造体をバラす構文が入っているという感じのことが多い(schemaなどではそれとは全く別に多値を返す事ができるけれど。一方でbindingのための構文が別途用意されている)。例えばpythonの例でいうと以下の様な感じ。

vs = (1, 2)
x, y = vs

単一のタプルをdestructuringした結果、それぞれの値が変数に束縛されるという形。 これがgolangでも同様だと思っていたのだけれど。実はちょっと違ったという話。

ふつうの分配束縛(のように見える)

golangでも多値を返す関数が定義できる(pair)。そしてpythonの例と同様の理屈でdestructuringが行われ、複数の引数を取る関数(add)に渡され使われる(ように見えていた)。

package main

import "fmt"

func pair(x int) (int, int) {
    return x, x + 1
}

func add(x int, y int) int {
    return x + y
}

func main() {
    x, y := pair(10)
    fmt.Println(add(x, y))
}

実は

実は、多値を返す関数の戻り値をそのまま複数関数に渡すことができる。こういう感じに。知らなかった。

package main

import "fmt"

func pair(x int) (int, int) {
    return x, x + 1
}

func add(x int, y int) int {
    return x + y
}

func main() {
    fmt.Println(add(pair(10)))
}

addはpairの呼び出しをそのまま引数として受け取っている。

よく考えてみれば

よく考えてみれば、たまに fmt.Println などを使う折に触れていた。 fmt.Println(parseFoo(v)) みたいなエラー値も含む戻り値の関数の呼び出しでも気にせずprintデバッグしていたような気がする。

実は仕様にも

実は仕様にもしっかり明記されている。

https://golang.org/ref/spec#Calls

As a special case, if the return values of a function or method g are equal in number and individually assignable to the parameters of another function or method f, then the call f(g(parameters_of_g)) will invoke f after binding the return values of g to the parameters of f in order. The call of f must contain no parameters other than the call of g, and g must have at least one return value. If f has a final … parameter, it is assigned the return values of g that remain after assignment of regular parameters.

何が嬉しいか

何が嬉しいかというと。エラー値を返す関数とpanicする関数の定義の扱いが便利になる。例えば通常の用途ではエラー値も返すParseFooを使い、テストや自明なところでは、エラーになったらpanicするMustFooを使うようにするという部分を少しの変更で対応できる。わざわざMustFooを定義する必要はなくMustだけを定義すれば良い。

package main

import (
    "errors"
    "fmt"
)

// ParsePositive :
func ParsePositive(n int) (int, error) {
    // 通常は文字列などかもしれない
    if n >= 0 {
        return n, nil
    }
    return n, errors.New("not positive")
}

// Must :
func Must(n int, err error) int {
    if err != nil {
        panic(err)
    }
    return n
}

func main() {
    n := Must(ParsePositive(10))
    fmt.Println("for test ", n)
}

Must(ParsePositive(10)) みたいな形ですむ。便利。知らなかった。

はてなブログの記事をアップロードするコマンドを作った

github.com

hatenaはoauth1.0aっぽいのでわりとだるかった。

インストー

$ go get github.com/podhmo/hatena/cmd/hatena

使い方

新規投稿と編集を手軽にやりたかった。投稿した時点でaliasを覚えてくれるので編集が楽。

# 新規投稿
$ hatena -alias foo foo.md
# 編集
$ hatena -alias foo foo.md
# 新規投稿(aliasが異なる)
$ hatena -alias boo boo.md

ちなみに aliasを付けなくても良くてdefaultでheadのaliasが付く。ただしaliasのオプションを付けなかった場合は常に新規投稿扱い。

# 新規投稿
$ hatena foo.md
# 編集
$ hatena -alias head foo.md
# 新規投稿(alias指定なし)
$ hatena foo.md

そういえば

事前に設定が必要。

  1. oauthのアプリを作る
  2. consumer key, consumer secretを埋めてアプリを実行
  3. access token, access secretを取得する

設定は以下の場所に入る

tree ~/.hatena
~/.hatena
├── config.json
└── hatena.history

こういう感じの構造

{
  "default_alias": "head",
  "hist_file": "~/.hatena/hatena.history",
  "consumer_key": "xxXXXxxxxxxxXxxx",
  "consumer_secret": "xXxxXxxXxxXxxxxxxXxxXxxxXxxx",
  "client_id": "XxxxxXxxxxxxxxxx",
  "client_secret": "XxXxXxxXXxxXXxxXxxxxxXXXxXXx",
  "hatena_id": "podhmo",
  "blog_id": "pod.hatenablog.com"
}

consumer_key, consumer_secretの取得はこのあたりを参考に

(client_id, client_secretは勝手に入る)

dictknife,jsonknifeの機能を整理

github.com

はじめに

json,yamlを扱う上で便利そうな機能を含んだ十得ナイフっぽい感じのライブラリを作っていた。それにコマンドをもたせた結果便利になってきたのでどういうときに何を使うかを整理しておく(完全に自分用のメモ)。

dictknife

dictknifeとjsonknifeという2つのコマンドを用意している。jsonknifeはjsonschemaやswaggerというかJSON関連の諸々に関連した機能を持っている。一方dictknifeはもう少しprimitiveなもの。

提供しているコマンドは以下

Usage: dictknife [OPTIONS] COMMAND [ARGS]...

Options:
  --log [NOTSET|ERROR|WARNING|WARN|INFO|DEBUG|CRITICAL]
                                  logging level
  -h, --help                      Show this message and exit.

Commands:
  concat     concat dicts
  diff       diff dict
  transform  transform dict

特に機能を網羅して紹介や説明をするという気も起きないし。あんまり意味が無い気がするのでどういうふうに使うかだけ書く。

concat

concatはその名前の通りに何かと何かを結合させるためのものではある。例えば以下の様な感じに。

$ dictknife concat --format json <(echo '{"name": "foo"}') <(echo '{"age": 20}')
{
  "name": "foo",
  "age": 20
}

ふつうのconcatと異なるのはネストした表現にも対応しているところ。

$ cat <<-EOS > person.yaml
definitions:
  person:
    type: object
    properties:
      name:
        type: string
      age:
        type: integer
EOS
$ cat <<-EOS > group.yaml
definitions:
  group:
    type: object
    properties:
      members:
        type: array
        items: "#/definitions/person"
EOS
$ dictknife concat person.yaml group.yaml
definitions:
  person:
    type: object
    properties:
      name:
        type: string
      age:
        type: integer
  group:
    type: object
    properties:
      members:
        type: array
        items: '#/definitions/person'

フォーマットを変換したい場合に

concatという名前の通り元々のファイルをつなげる事が目的のコマンドだった。とは言え1つのものに対してフォーマットを変えたい場合にも使う。意外と便利。 --dst で拡張子を付けても良いし。 –output-formatで出力するformatを変えても良い。

$ dictknife concat --output-format yaml --input-format json <(echo '{"name": "foo"}') <(echo '{"age": 20}')
name: foo
age: 20
$ dictknife concat --output-format toml --input-format json <(echo '{"name": "foo"}') <(echo '{"age": 20}')
name = "foo"
age = 20

対応している拡張子は今のところ.yaml(.yml),.json.toml。

diff

diffはその名の通りdiff。ソートした結果に対してdiffを調べてくれるので順序の処理が甘い感じのコマンドの出力結果を調べるのに便利。

$ cat <<-EOS > person0.yaml
person:
  name: foo
  age: 20
EOS
$ cat <<-EOS > person1.yaml
person:
  age: 20
  name: foo
EOS
$ dictknife diff person{0,1}.yaml

もちろんふつうのdiffでは差分が存在する。

$ diff -u person{0,1}.yaml
--- person0.yaml    2017-05-27 22:59:26.000000000 +0900
+++ person1.yaml    2017-05-27 22:58:47.000000000 +0900
@@ -1,3 +1,3 @@
 person:
-  name: foo
   age: 20
+  name: foo

deserializeされた後のsictに対するdiffを見るので順序には依存していない。ただ出力結果がJSONになっているのがちょっと不便といえば不便かもしれない。

$ cat <<-EOS > person2.yaml
person:
  age: 20
  name: bar
  nickname: b
EOS
$ dictknife diff person{0,2}.yaml
--- person0.yaml
+++ person2.yaml
@@ -1,6 +1,7 @@
 {
   "person": {
     "age": 20,
-    "name": "foo"
+    "name": "bar",
+    "nickname": "b"
   }
 }

あと、昔の実装では単にjson.dumps時にsort_keysをTrueにすれば良いだろうとだけ思っていたのだけれど。そうでもない。例えば、yaml上の表現としてkeyに数値が許されるのだけれど。JSON上はkeyは文字列と規程されている。そのため以下の様なデータを渡したとき失敗していた。

$ cat <<-EOS > status.yaml
200:
  ok
default:
  hmm
EOS
$ dictknife diff status.yaml status.yaml
TypeError: unorderable types: str() < int()

これに --normalize オプションを付けてあげるとkeyを文字列に変換してから比較してくれるので問題がなくなる。

$ dictknife diff --normalize status.yaml status.yaml

transform

dictknife transformはその名の通り変換。よく使うのは --code でのeval的な記述。

$ cat status.yaml
200:
  ok
default:
  hmm

$ cat status.yaml | dictknife transform --code='lambda d: [d,d,d]'
- 200: ok
  default: hmm
- 200: ok
  default: hmm
- 200: ok
  default: hmm

上の例では特に意味のない変換だったけれど。昔はjsonknife derefとの組み合わせで使う事があった(今ではunwrap,wrapのペアやrefの指定方法の進化で不要になった)。

これが必要になったらある意味負け。ただloadとdumpを繰り返すような変換処理があった場合にこれ経由で呼びだすと便利みたいなことはある。

$ cat <<-EOS > upcase.py
def upcase(d):
    if hasattr(d, "keys"):
        return {upcase(k): upcase(v) for k, v in d.items()}
    elif isinstance(d, (list, tuple)):
        return [upcase(d) for e in d]
    else:
        return str(d).upper()
EOS
$ cat <<-EOS > person.yaml
definitions:
  person:
    type: object
    properties:
      name:
        type: string
      age:
        type: integer
EOS
$ cat person.yaml | dictknife transform --function "./upcase.py:upcase"
DEFINITIONS:
  PERSON:
    PROPERTIES:
      AGE:
        TYPE: INTEGER
      NAME:
        TYPE: STRING
    TYPE: OBJECT

kamidanaのreadmeの生成にkamidanaを使うことにした

github.com

kamidanaのreadmeの生成にkamidanaを使うことにした。便利で良かった。ちょっとしたセルフホスティング的な何か(意味的には違う)という感じになり面白かったのでちょっとだけ文章にしてみる。あとjinja2にけっこう便利な組み込みのフィルターが存在することに気づいていなかった(組み込みのフィルターはこのあたりに書いてある(実際はコードを覗いた方が早い))。

便利なfilter

個人的に便利だと思ったのはindentというフィルター。これとReSTの相性がとても良い。特に以下の様なフィルターを用意してindentと一緒に使うと便利だった。

import subprocess
from kamidana import as_filter


@as_filter
def read(filename):
    with open(filename) as rf:
        return rf.read()


@as_filter
def spawn(cmd, encoding="utf-8"):
    p = subprocess.run(
        cmd,
        shell=True,
        check=True,
        stdout=subprocess.PIPE,
        stderr=subprocess.STDOUT,
    )
    return p.stdout.decode(encoding)

ちょっとしたファイルの参照にread + indent

ちょっとしたコードをcode-blockでwrapして載せるのにはread + indentが便利。例えば以下の様なpythonのコードがあったとして

def hello():
    return "hello"

これをReST上に載せると以下のようになる。インデントが必要になるのが面倒くさい。

.. code-block:: python

  def hello():
      return "hello"

ここで先程のreadとindentのフィルターを使うと以下の様に書ける。

.. code-block:: python

{{"./hello.py"|read|indent(2, True)}}

先頭もインデントしてほしければ、第二引数にTrueを渡す。

コードの実行結果を載せるのにspawn + indent

何らかのリポジトリにコマンドの実行結果を載せたい場合はよくある。このときにもjinja2のindentが便利。例えばlsのコマンドの結果をsortした結果を載せたりしたい場合に以下の様に書く。

.. code-block:: bash

  $ ls -l | sort
  <ls -l | sortの結果をコピペ>

これを先程のspawnを利用して以下の様に書くことができる。with extensionsも有効にしておくと便利。

.. code-block:: bash

{% with cmd="ls -l | sort" %}
  $ {{cmd}}
  {{cmd|spawn|indent(2)}}
{% endwith %}

というよりもここまで書いてみて思ったのだけれど。jinja2が便利と言うよりはReSTを扱うのにインデントを強要されるのがだるく。このインデントの対応にjinja2のindentフィルターがとても便利ということだった。

そんなわけでkamidanaのreadmeを書くのにkamidanaを使った

そんなわけでkamidanaのreadmeを書くのにkamidanaを使った。Makefileでreadmeを呼ぶとreadmeが生成される。Makefileはこういう感じ。 (additionals.pyにspawn,readが定義されている)

readme:
  kamidana misc/readme.rst.jinja2 --additionals misc/additionals.py > README.rst

このコミット https://github.com/podhmo/kamidana/commit/45c8a5c29622354a30e74eeb62feb5eb8a75f25f

テンプレートに埋め込む際の環境変数からの情報取得について

github.com github.com

jinja2テンプレートに埋め込む際に何だかんだで環境変数からの情報が取得できると便利。なので環境変数から取得する方法について考えたりしてみた。

j2cliの場合

元々kamidanaを作る発端となったパッケージに、j2cli というものがあった。こちらはどうなっているかというと。os.environを読み込むだけ。やばい。全ての環境変数がtemplateから見えるのはどうなんだという気持ちがあったりした。

あと、j2cliは複数のsourceから情報を読む事はできないみたいなので、設定の大部分を別のファイルから読み取り、環境変数を使って一部だけ設定を上書きするみたいなことはできない。

ホワイトリストを使って環境変数から読む方法

さすがに全部の環境変数が見えるのは嫌だったのでホワイトリスト形式で読み込むことにした。環境変数を利用して読み取りたい場合には、末尾に “.env” または “.environ” で終わるファイル名のファイルを使うことにする。そしてこれらのファイルの形式はこのsuffixを取り除いたファイル名から決めることにする。例えば、yamlで定義されたホワイトリストの名前は <filename>.yaml.env などになる。

そして、変換後のdictのペアのvalue部分を環境変数から取得するkey名とすることにする。

例えば以下の様なperson.yaml.envがあった場合には、環境変数の “NAME” と “AGE” を見ることにする。

person:
  properties:
    name: NAME
    age: AGE

そしてその環境変数名で引いた値をホワイトリストのファイルのvalue部分に焼き付けた値を設定値とすることにする。 例えば、こういう感じ。

$ NAME=foo AGE=20 dictknife concat person.yaml.env
person:
  properties:
    name: foo
    age: '20'

型を指定したい場合

これはoptionalな機能ではあるけれど。型を指定したい場合がある。先程の例では環境変数から値を取得したのですべての値が文字列になっている。 ageは数値を利用したい事があるかもしれない。この場合に型(というかpythonの組み込みのtype)を":“付きで後置で修飾することにする。以下の様に書く。

person2.yaml.env

person:
  properties:
    name: NAME
    age: AGE:int

AGE部分がintの値になってほしい場合。

$ NAME=foo AGE=20 dictknife concat person2.yaml.env
person:
  properties:
    name: foo
    age: 20

20はintになっている。

kamidanaはdictknifeに依存している

kamidanaはdictknifeに依存しているので上の機能がdictknife上で実装されたらそれがそのまますぐに使える。

--dump-context

その前にkamidanaに --dump-context というオプションを追加した。これは --data により読み込まれたデータがどのようなものであったか判断するのに役に立つ。

例えば以下の様なtemplateと設定ファイルがあるとする。

template.j2

{{name}}({{age}}): hai.

person.yaml

name: foo
age: 20

これをkamidanaで実行すると以下のような結果になる。

$ kamidana --data ./person.yaml template.j2
foo(20): hai.

どのようなデータが読み込まれているか見たい場合に --dump-context が使える。

$ kamidana --data ./person.yaml template.j2 --dump-context
{
  "name": "foo",
  "age": 20,
  "template_filename": "template.j2"
}

jsonで出力されるのが無難そうなので、jsonで出力されるようにした(このあたりは変えるかもしれない)。

環境変数から設定を読み取ってtemplateを使う

kamidanaはdictknifeに依存しているので上の機能がdictknife上で実装されたらそれがそのまますぐに使える。 先程実装した環境変数から設定を読み込む処理を使って同様のことをやってみる。

NAMEとAGEを環境変数から取り出している。

$ NAME=bar AGE=10 kamidana --data ./person.yaml.env template.j2 --dump-context
{
  "name": "bar",
  "age": 10,
  "template_filename": "template.j2"
}
$ NAME=bar AGE=10 kamidana --data ./person.yaml.env template.j2
bar(10): hai.

j2cliとは異なり、一部分だけを環境変数で上書きということも出来る。名前だけ環境変数経由でbarに変えてみる。

$ NAME=bar kamidana --data ./person.yaml --data ./person.yaml.env template.j2 --dump-context
{
  "name": "bar",
  "age": 20,
  "template_filename": "template.j2"
}
$ NAME=bar kamidana --data ./person.yaml --data ./person.yaml.env template.j2
bar(20): hai.

--data オプションで後方に来たもので上書きされる。

結局昨日のロガーの話はパッケージにした

github.com

結局昨日のロガーの話はパッケージにした。100行以下で大変短く良いコード。 ただ、stdoutやstderrに出力するだけで構造化ログを実装したと言ってはだめで、何らかのdata sourceに溜め込んでそれを何らかのビューから覗くぐらいは試した方が良いのだけれど。そこまで真面目に試すやる気は出ない。

使い方

使い方はかんたんで pip install monokaki をしてから。ほぼ通常のloggingモジュールを使う感じにするだけ。

from monokaki import get_logger, basic_config, INFO as INFO_LEVEL
logger = get_logger(__name__)


def hello(log):
    log.bind(age=20).info("hello")
    log.info("bye", age=20)


def main():
    hello(logger.bind(name="foo"))


if __name__ == "__main__":
    basic_config(level=INFO_LEVEL)
    main()

出力結果

{"age": 20, "level": "INFO", "logger": "__main__", "msg": "hello", "name": "foo", "time": "2017-05-21 21:00:45,524"}
{"age": 20, "level": "INFO", "logger": "__main__", "msg": "bye", "name": "foo", "time": "2017-05-21 21:00:45,526"}

かんたんですね。いつも通りの感じ。

出力の形式を変えたい場合

出力形式を変えたい場合にはrenderer関数を作ってあげれば良い。renderer関数は辞書とlogging.LogRecordとlogging.Formatterを受け取るcallable object。関数で良い。例えばltsvで出力したい場合は以下の様な感じになる。順番なども気にしたい場合にはOrderedDictを使う。

from collections import OrderedDict


def ltsv_renderer(d, record, formatter):
    c = OrderedDict()
    c["time"] = formatter.formatTime(record)
    c["level"] = record.levelname
    c["msg"] = record.msg
    c["where"] = "{}:{}({})".format(record.filename, record.lineno, record.funcName)
    c.update(sorted(record.kwargs.items()))
    return "\t".join("{}:{}".format(k, v) for k, v in c.items())

LogRecordの扱いだけは見慣れない人もいると思うけれど。基本的にはドキュメントに書いてあるものが使えるだけ。あとは、bindなどで渡された引数はrecord.kwargsに格納されている。

これを使った結果

from monokaki import get_logger, basic_config, INFO as INFO_LEVEL
from collections import OrderedDict
logger = get_logger(__name__)


def hello(log):
    log.bind(age=20).info("hello")
    log.info("bye", age=20)

def main():
    hello(logger.bind(name="foo"))


if __name__ == "__main__":
    basic_config(level=INFO_LEVEL, renderer=ltsv_renderer)  # ここで新しく定義したltsv_rendererを使っている
    main()

こういう感じに出力は変えられる。

time:2017-05-21 21:08:18,661 level:INFO  msg:hello   where:main.py:17(hello) age:20  name:foo
time:2017-05-21 21:08:18,661    level:INFO  msg:bye where:main.py:18(hello) age:20  name:foo

もちろんexc_infoなどに対応することもできて、こう書いてあげると。exc_infoがまともに動く。

def ltsv_renderer(d, record, formatter):
    c = OrderedDict()
    c["time"] = formatter.formatTime(record)
    c["level"] = record.levelname
    c["msg"] = record.msg
    c["where"] = "{}:{}({})".format(record.filename, record.lineno, record.funcName)
    c.update(sorted(record.kwargs.items()))
    if "stack" in d:
        c["stack"] = d["stack"].replace("\n", "\\n")
    return "\t".join("{}:{}".format(k, v) for k, v in c.items())

こういう感じ。

def hello(log):
    log.bind(age=20).info("hello")
    log.info("bye", age=20)
    try:
        1 / 0
    except:
        logger.info("1/0", exc_info=True)

stackが追加されている。

time:2017-05-21 21:12:59,552 level:INFO  msg:hello   where:main.py:19(hello) age:20  name:foo
time:2017-05-21 21:12:59,552    level:INFO  msg:bye where:main.py:20(hello) age:20  name:foo
time:2017-05-21 21:12:59,553    level:INFO  msg:1/0 where:main.py:24(hello) stack:Traceback (most recent call last):\n  File "main.py", line 22, in hello\n    1 / 0\nZeroDivisionError: division by zero

Formatterを作っているだけなので

logging.Formatterを作っているだけなので。その他のloggingの設定とかちあうこともない。

import logging
from monokaki import StructuralFormatter
from monokaki import get_logger
import sys

logger = get_logger("my log")
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(StructuralFormatter())

# loggerAdapterなので内部のloggerを取り出すにはlogger.logger
logger.logger.addHandler(handler)
logger.setLevel(logging.INFO)

logger.info("hai", name="foo", age=20)
logger.logger.info("hai name=%s, age=%d", "foo", 20)

かちあうこともない。

{"age": 20, "level": "INFO", "logger": "my log", "msg": "hai", "name": "foo", "time": "2017-05-21 21:20:37,497"}
INFO:my log:hai name=foo, age=20

標準ライブラリの範囲で構造化ログで出力するようにしてみる

構造化ログ?

通常のloggingライブラリなどで使われるログをテキストログと呼ぶとすると、構造化ログとテキストログには以下の様な違いがある。

テキストログ

  • ログは人が読むもの
  • 通常テキストファイルに出力され、grepなどにより該当するログを見つける
  • 1つのログの単位はテキスト(文字列)
  • (パラメーターを自由に付けたりというのはむずかしい)

構造化ログ

  • ログは機械が読むもの
  • 何らかのアプリケーションにより検索され、何らかのビューから情報を確認する
  • 1つのログは何らかの構造化された表現(e.g. JSON)
  • (パラメーターを自由に付加できる)

すごく雑にいうとテキストログと言うのは以下のような出力のものを指してる。

2017-05-20 21:13:44,296 INFO:app:hello
2017-05-20 21:13:44,296 ERROR:app:broken
Traceback (most recent call last):
  File "~/sandbox/daily/20170520/example/broken.py", line 7, in broken
    return 1 / 0
ZeroDivisionError: division by zero

一方で構造化ログと言うのは以下のようなもの(通常はフォーマットされていない)。

{
  "time": "2017-05-20 21:15:24,348",
  "level": "INFO",
  "meg": "hello",
  "caller": "~/sandbox/daily/20170520/example/hello.py:8",
  "source": "app",
  "age": 20,
  "name": "foo"
}
{
  "time": "2017-05-20 21:15:24,348",
  "level": "ERROR",
  "meg": "broken",
  "caller": "~/sandbox/daily/20170520/example/broken.py:9",
  "source": "app",
  "stack": "Traceback (most recent call last):\n  File \"~/sandbox/daily/20170520/example/broken.py\", line 7, in broken\n    return 1 / 0\nZeroDivisionError: division by zero"
}

構造化ログの場合は、一度出力された後にcollector的なものが送信を行うにせよ、fluentdなどの何らかのブローカー的なものに丸投げするにせよ、最終的にはどこかのシステムのdata sourceとなり溜まっていく感じになると思う。

(パラメーターを自由に付けたりというのはむずかしい)という話

(パラメーターを自由に付けたりというのはむずかしい)という話。これに関しては括弧書きの理由は完全にそうと言えるわけではないし。作りが貧弱なせいもあるので何とも言えないのだけれど。これはこういう話のことを指していた。

pythonのloggingモジュールのロガーは、情報の呼び出しに付加的な情報をつける事ができる。最終的に文字列になるという話なら当然フォーマット文字列で済む話しではあるし。以下の様な感じで文字列を生成してあげれば良い(生成された文字列をそのままロガーに渡さないのはsentryなどでaggregateされたときなどのことを考えると自明ですね)。

logger.info("error is occured errno: %d", 404)
# 2017-05-20 21:27:04,692 INFO:__main__:error is occured errno: 404

また、loggingのロガーはログのフォーマットを変えたりすることもできて、ここに何を出力したいかを指定してあげる事もできる。例えば上の表示を以下の様に変える事もできる。

fmt = "%(asctime)s: level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
logging.basicConfig(level=logging.INFO, format=fmt)
logger.info("error is occured errno: %d", 404)

# 2017-05-20 21:29:40,159: level=INFO main.py:6 -- error is occured errno: 404

ここで利用できる属性は ドキュメントに書いてあるLogRecordの属性の部分だけなのだけれど。

extra というキーワードを付けることで、追加で利用できる属性を増やすことができる。

extraの罠

例えば、以下の様にして何らかの情報を追加できる。meという属性を追加できるようにしてみた。そしてログ出力時には me="(o_0)" という値を渡している。

# fmt = "%(asctime)s: level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
fmt = "%(asctime)s: me=%(me)s level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
logging.basicConfig(level=logging.INFO, format=fmt)
logger.info("error is occured errno: %d", 404, extra={"me": "(o_0)"})

# 2017-05-20 21:34:50,188: me=(o_0) level=INFO main.py:6 -- error is occured errno: 404

extraで渡されたmeが実際に上手くログに反映されてはいるのだけれど。これでは問題がある。この新たに追加されたmeを渡していないログの呼び出しはエラーになってしまう。

logger.info("ok")

こういう感じにエラーになる(meは必須なのに見当たらないという話)。

--- Logging error ---
Traceback (most recent call last):
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 980, in emit
    msg = self.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 830, in format
    return fmt.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 570, in format
    s = self.formatMessage(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 539, in formatMessage
    return self._style.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 383, in format
    return self._fmt % record.__dict__
KeyError: 'me'
Call stack:
  File "main.py", line 13, in <module>
    main()
  File "main.py", line 6, in main
    logger.info("ok")
Message: 'ok'
Arguments: ()

さすがにこんなに引数にセンシティブなログは使いたくない気持ちを持つ人が多い。はず。そもそもこの方針はあんまり良くない。

extraはあんまり使いたくない

formatでの属性の追加は何かcontextualな情報を渡すための機能では無さそう。もうちょっとアプリの実行時には静的に決まっている情報などを付加的に表示するための機能のような気がしてきた。例えば実行時のhostなんかを載せたりだとか。そのためにfilterみたいな機能もある。

handlerとの関係を意識しないと使えないけれど。以下の様な感じで。

class HostInjector(logging.Filter):
    def __init__(self, name="", host=None):
        super().__init__(name)
        self.host = host

    def filter(self, record):
        record.host = self.host
        return True

def main():
    logger.info("ok")


if __name__ == "__main__":
    fmt = "%(asctime)s: host=%(host)s level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(logging.Formatter(fmt))
    handler.addFilter(HostInjector(host="127.0.0.1:4444"))
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

こういう感じ。ログ出力に localhost:4444 というホストの情報を埋め込んでいる。

2017-05-20 22:00:58,859: host=127.0.0.1:4444 level=INFO main.py:17 -- ok

もう少し丁寧に説明すると、loggerは複数のhandlerを持ち、handlerはそれぞれ自分に割り当てられた処理をする(例えば上の例ではStreamHandlerが標準出力にメッセージを出力する)。handlerが利用する出力自体はFormatterが作成する。またloggerやhandlerは自身に渡ってきた情報を元に部分的に修正を加えるような変換を持つ事ができる。この変換はfilterによって行われる。と言うような感じ。

元々のloggingが持っている情報も込みで構造化ログを行いたい

extraで情報を与えることもできて、メッセージの出力結果が加工出来るようになったところで、構造化ログの話に戻ると、構造化ログはそもそも自由だった。自由にパラメータを付加する事ができるのだった。一方で既存のFormatterとformat文字列を渡す枠組みではそれに上手く対応する事ができない。

構造化ログの自由な引数の受け渡しに対応するためには何が必要かを整理してみる。

  • Loggerは、渡されたログ出力のためのイベントを生成する
  • Handlerは、イベントを待ち受ける。自分に渡されたイベントに従ったアクションを行う
  • Formatterは、渡されたイベントから生成されたメッセージ(正確にはLogRecord)を、整形して好みの出力表現に変える

まずFormatterは変える必要はありそう。

単純なformatterを作ってみる

単純なformatterを作ってみる。とりあえず、meを渡してみることにした。formatterはjson形式でdumpしている。

import json
import sys
import logging
logger = logging.getLogger(__name__)


class StructuralFormatter:
    def format(self, record):
        d = {"msg": record.msg, "me": record.me, "level": record.levelname}
        return json.dumps(d)


def main():
    logger.info("ok", extra=dict(me="(o_0)"))


if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

結果はこの通り。

{"msg": "ok", "level": "INFO", "me": "(o_0)"}

ただ問題が2つ位ある。1つは大した事がないのだけれど。あとの2つはとても問題。

  • loggerを使う際のextraが面倒くさい
  • ある特定の属性を付加することは出来るが、任意の属性を付加するということができていない。
  • 他のloggerに影響を与えるかもしれない(かもしれない)

後者がとても問題。問題の根本はどこにあるかというと、内部で作られるメッセージオブジェクト(LogRecord)が余分な情報(extra)を全部自分自身の属性としてsetattrしてしまう点。varsとかしてしまえば全部の情報を保持してしまうし。一方でデフォルトの情報を取り除くみたいな実装もしたくはない。

ちなみにvarsをrecordに対して使うとこういう感じの出力になる(フォーマットはしている)。

{
  "args": [],
  "lineno": 14,
  "relativeCreated": 1.5249252319335938,
  "msg": "ok",
  "exc_text": null,
  "module": "main",
  "processName": "MainProcess",
  "filename": "main.py",
  "process": 93274,
  "threadName": "MainThread",
  "funcName": "main",
  "levelname": "INFO",
  "created": 1495286618.802307,
  "levelno": 20,
  "me": "(o_0)",
  "thread": 140735293480960,
  "stack_info": null,
  "name": "__main__",
  "exc_info": null,
  "msecs": 802.3068904876709,
  "pathname": "main.py"
}

救世主はLoggerAdapter

loggingモジュールはLoggerAdapterというクラスも用意してくれている。これは何かと言うとLoggerのインターフェイスを持ったもののAdapterでprocess()を提供している。このオブジェクト経由で呼ばれた通常のログ出力のメソッド(info()やdebug()などのこと)は必ずこのprocess()を経由して内部に保持したロガーに渡される。そんなわけで、以下のようにLoggerAdapterを継承したクラスを使ってwrappingしてあげると良いことが起きる。

class StructLogger(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        information = {
            "extra": {
                "kwargs": kwargs,
                "structual": True,
            }
        }
        return msg, information


def get_logger(name):
    return StructLogger(logging.getLogger(name), {})


class StructuralFormatter:
    def format(self, record):
        d = {"msg": record.msg, "level": record.levelname}
        d.update(record.kwargs)
        return json.dumps(d)


def main():
    logger = get_logger(__name__)
    logger.info("ok", me="(o_0)")

良いことの1つ目はlogger.info等を利用したときの余分なextraの引数が不要になったこと。そしてもう1つの良いことは任意の引数に対応出来るようになったということ(実質kwargsというextraが渡されているだけなのでFormatterではkwargsを見るだけで良い)。

ただこれだけでは実用に耐えないのでもうちょっと頑張る必要がある

他のloggerと干渉しないformatterを作りたい

他のloggerと干渉しないformatterになるようにしたい。上で作った実装ではLoggerAdapterでラッピングしたオブジェクトを作るための独自のget_loggerを作っていた。とは言え既存のコードやライブラリの中ではこの独自のget_loggerではなく。通常の logging.getLogger が使われているということもありそうではある。これが干渉してしまってエラーにってはマズイ。

当然ではあるけれど、独自の get_logger を使わないで作ったloggerのログ出力はextraで期待した情報を含んでいないのでエラーが発生する。

logging.getLogger(__name__).info("ng")
# AttributeError: 'LogRecord' object has no attribute 'kwargs'

これを直したい。治す方法はそんなに大変ではなく、作ったAdapterでは何らかのマーカー的な情報(structual=True)を渡して、Formatterではそのマーカーを見て処理を分岐させれば良い。

class StructLogger(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        information = {
            "extra": {
                "kwargs": kwargs,
                "structual": True,
            }
        }
        return msg, information


def get_logger(name):
    return StructLogger(logging.getLogger(name), {})


class StructuralFormatter:
    def __init__(self, formatter=None):
        self.formatter = formatter or logging.Formatter(logging.BASIC_FORMAT)

    def format(self, record):
        if getattr(record, "structual", False):
            return self.formater.format(record)
        d = {"msg": record.msg, "level": record.levelname}
        d.update(record.kwargs)
        return json.dumps(d)

今度は大丈夫。

logger = get_logger(__name__)
logger.info("ok", me="(o_0)")

raw_logger = logging.getLogger(__name__)
raw_logger.info("ng")

# {"msg": "ok", "me": "(o_0)", "level": "INFO"}
# INFO:__main__:ng

例外情報の取得

標準のloggingライブラリはexc_info=Trueをつけていれば例外情報をstack_info=Trueをそのときのスタックの情報を付加して出力してくれる。この機能も有効にしたい。

このstacktrace関連の機能、loggerをラップしたオブジェクトから呼ぶと意図しない位置を見たりしてしまう。だとか色々な懸念があってあんまり触れたくないな〜みたいな感じの気持ちになっていたりしたのだけれど。真面目にloggingモジュールのコードを読んだ結果。loggingモジュールに定義されているオブジェクトに限り特別扱いの優遇措置を行なってくれているので、これもそんなに大変ではなくちょっとした修正で対応できる。

@@ -9,7 +9,9 @@
             "extra": {
                 "kwargs": kwargs,
                 "structual": True,
-            }
+            },
+            "stack_info": kwargs.pop("stack_info", False),
+            "exc_info": kwargs.pop("exc_info", False),
         }
         return msg, information
 
@@ -26,14 +28,18 @@
         if not getattr(record, "structual", False):
             return self.formatter.format(record)
         d = {"msg": record.msg, "level": record.levelname}
+        if record.exc_info:
+            d["stack"] = self.formatter.formatException(record.exc_info)
+        if record.stack_info:
+            d["stack"] = self.formatter.formatStack(record.stack_info)
         d.update(record.kwargs)
         return json.dumps(d)

これでこのstack_info=Trueを付加してstack traceを一緒に表示させたいコードの結果は

def main():
    logger = get_logger(__name__)
    logger.info("ok", me="(o_0)", stack_info=True)
    logging.getLogger(__name__).info("ng", stack_info=True)


if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

以下のようになる。stackという部分にstack traceの情報が詰まっている。整形方法などは既存のformatterにおまかせしている。

{"me": "(o_0)", "stack": "Stack (most recent call last):\n  File \"main.py\", line 49, in <module>\n    main()\n  File \"main.py\", line 41, in main\n    logger.info(\"ok\", me=\"(o_0)\", stack_info=True)", "msg": "ok", "level": "INFO"}

INFO:__main__:ng
Stack (most recent call last):
  File "main.py", line 49, in <module>
    main()
  File "main.py", line 42, in main
    logging.getLogger(__name__).info("ng", stack_info=True)

(内部的にスタックトレースの取得に使っているloggingのfindCallerというメソッドが自分自身のsourceファイル(logging/init.py)だけは特別扱いしてくれているので、LoggerAdapterを経由してのラッピングなら、ログ出力の実行位置を気にすること無く期待通りの結果を返すのも嬉しい(例えば、filenameやlinenoなどの情報など))

contextual logging

contextual loggingについて

LoggerAdapterを使ったことには、もう1つ幸運が隠されていて。それはcontextual loggingに対応する事がとても簡単なこと。contextual loggingとは何かというと、コード中の実行時のそのスコープに依存した情報を保持して蓄えたロガーを提供できるという機能。

例えば、structlogというライブラリでもこれらの機能は利用する事ができる。

"""
実行時の関数の呼び出し関係は以下の様になっていて、hでは渡されていない情報をログ出力では利用したいということがある。
f:
  g:
    h:
"""

import time
from structlog import get_logger


def f(logger, x):
    logger = logger.bind(time=time.time()).bind(f="on f")
    return g(logger, x)


def g(logger, x):
    logger = logger.bind(g="on g")
    return h(logger, x)


def h(logger, x):
    logger = logger.info("h is called")
    return x * x


if __name__ == "__main__":
    logger = get_logger(__name__)
    f(logger, 10)
    logger.info("end")

hで呼び出されたloggerはそのスコープの文脈に依存した情報(f,g,time)を持っているのでログ出力時にそれらに関する情報も出力する。一方でトップレベルのロガーには影響を与えていない。

time=1495288627.372377 f='on f' g='on g' event='h is called'
event='end'

こういうできごとは例えばバッチ処理を書くときなどにけっこう起きる。ロギングが難しいのは通常の関数ではlexical scope的なもので良い一方でロギングに使う値に関しては一部dynamic scope的(実行時の呼び出し関係のトップレベルの情報)な情報が欲しくなる。例えばバッチのトップレベルでbatch idみたいなものを情報として付加しておきたいが、後々の末端の操作ではbatch idから取得したもっと瑣末な値が対象になっている。一方でログ出力にはどのバッチの処理だったかも記録したいのでbatch idが含まれて欲しい。そういう感じ。こういう自体に対応するためにcontextual loggingはある。

一方で、そのためにはロガーもしくはそれを保持した値を持ち回らないとだめにはなってしまっている。

contextual loggingへの対応

構造化ログはしばしばcontextual loggingへの対応を謳っている事が多い。今まで作ってきたロガーでも対応してみることにしよう。structlogと同様にbindというメソッドをもたせるようにしてみる。

これは実はそんなに大変ではなくって、今まで作っていたLoggerAdapterにメソッドをちょっと追加して変更を加えるだけで良い。

@@ -1,8 +1,14 @@
+from collections import ChainMap
+
+
 class StructLogger(logging.LoggerAdapter):
+    def bind(self, **kwargs):
+        return self.__class__(self.logger, ChainMap(kwargs, self.extra))
+
     def process(self, msg, kwargs):
         information = {
             "extra": {
-                "kwargs": kwargs,
+                "kwargs": ChainMap(kwargs, self.extra),
                 "structual": True,
             },
             "stack_info": kwargs.pop("stack_info", False),

これで contextual logging の対応は終わる。先程のstructlogで行なったコードの例はこちらでも動く。

def main():
    logger = get_logger(__name__)
    f(logger, 10)
    logger.info("end")

if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()
{"level": "INFO", "time": 1495289299.355759, "f": "on f", "g": "on g", "msg": "h is called"}
{"level": "INFO", "msg": "end"}

最後の状態のgistはこんな感じ

https://gist.github.com/podhmo/c8b15022fd4b09c9c15e45f1f511f697

ちなみにlogging.StreamHandlerを使っているのでstringであることを前提にしているけれど。辞書のまま使いたいのであればそのようにコードを変更する事もできる。また内部的に使う辞書をOrderedDictにすれば好みの順序でのログ出力もされるようになる。

参考