Elixir 的日志功能由 Logger 模块提供,它基本上是 Erlang 的 :logger
的封装。
Elixir 的日志支持 7 个级别:
:emergency
- 当系统不可用时,会发生恐慌:alert
- 用于警报,必须立即采取的操作,例如数据库损坏:critical
- 用于严重情况:error
- 用于错误:warning
- 用于警告:notice
- 用于正常但重要的消息:info
- 用于任何类型的信息:debug
- 用于调试相关消息
当然常用的还是 :error
到 :info
之间的几个。每个级别都有对应的函数用来记录日志,支持结构化数据和非结构化数据,以及返回结构化或非结构化数据的零元函数。
所谓结构化数据就是 keyword list 和 map,Elixir 也称之为“report”。非结构化数据就是字符串或字符串列表。其实在最开始,Logger 还支持任何实现了
String.Chars
协议的数据,虽然目前依然受到支持,但是已经被标记为“deprecated”了,因此这里也建议不要这样用。
以上级别对应的函数应该都是宏,因此低于当前配置级别的日志的参数也不会被求值,这是一个很棒的特性,避免日志参数中的复杂表达式影响系统新能。但是它可以通过 :always_evaluate_messages
配置来启用始终求值,默认是关闭的。还有一个例外就是 bare_log/3
函数,它是一个比较底层的函数,也会始终求值参数,除非参数是匿名函数。
除了用于日志记录的数据,它们还支持传入一个“元数据”,所谓“元数据”是一个 keyword list,默认为 []
,关于元数据的使用我们后面在详细说明。
Elixir 中日志是一个应用,通常在 mix.exs
的 application/0
中启动它:
def application do
[
extra_applications: [:logger]
]
end
Logger
需要通过 require
导入,然后通过 Logger.info
等来记录日志。
defmodule MyModule do
require Logger
def hello(%{} = param) do
Logger.notice("call hello")
Logger.info(param)
end
end
接下来我们来看看日志的一些配置。
基本配置
关于日志的配置,官方文档其实写的不太好理解,对于初学者来说并不友好。要搞明白日志的配置逻辑,我们首先要理解配置的逻辑。
所谓配置其实就是应用的“环境”。在 Elixir 中,我们在 mix.exs
文件中通过 application/0
函数来定义应用,它返回一个包含应用信息的 keyword list。其中有个叫 :env
的键,它的值也是一个 keyword list,这就是该应用的”环境”。
由于在 application/0
中写配置不太方便,于是我们将配置独立到了 config/config.exs
文件中,Mix 会负责将配置文件中的键值对合并到应用的“环境”中。
Config
给我们提供了两个配置函数:
config(root_key, opts)
(1)config(root_key, key, opts)
(2)
root_key
不用想,一定是应用名。对于第一个函数, opts
必须是一个 keyword list,相当于批量键值对配置。对于第二个函数, key
必须是原子, opts
则可以是任意类型,相当于单一键值对配置。如果能理解上面的内容,那么就能理解下面的这两个配置其实是等价的:
# 1
config :my_app, score: 100
# 2
config :my_app, :score, 100
回到日志的配置,因为日志是做为独立应用启动的,所以在配置时, root_key
必须是 :logger
。
Elixir 的日志是前后端分离的设计,客户端负责格式化和截断,具体的日志记录交给后端的日志处理程序。所以在配置的时候,我们要明白自己到底在配置哪一块,是前端?还是后端?搞清楚这一点对理解日志的配置非常重要。总体来说,在日志中我们可以有以下配置键:
:level
- 日志级别,支持运行时修改:translator_inspect_opts
- 配置转换OTP错误消息的行为,支持运行时修改:always_evaluate_messages
- 总是求值日志参数,默认false
:compile_time_application
- 编译期设置:application
元数据:compile_time_purge_matching
- 编译期“修剪”日志:default_formatter
- 配置默认的格式化程序:default_handler
- 配置默认的日志处理程序(后端):handle_otp_reports
- 是否记录OTP消息,默认为true
:handle_sasl_reports
- 是否记录监督,崩溃和进程报告,默认为false
以上配置其实大部分都不常用,所以我会按常用到不常用的顺序尽量把每个配置的作用都介绍到,有些配置前后会有一些穿插依赖,前边看不懂没关系,后面一定会讲明白的。
日志级别
日志级别是我们最常用的配置,除了前面看到的7个级别,还支持下面两个配置:
:all
- 记录所有消息,相当于:debug
。:none
- 禁止记录所有消息,相当于关闭日志。
注意,我们这里说的是前端的级别控制,实际上日志后端也有日志级别控制,相当于是有两层过滤。直接在 :logger
下配置的是前端的日志级别,在 :default_handler
下配置的是后端的日志级别,它用来配置日志处理程序,下一章我们会看到。
config :logger,
level: :info,
default_handler: [level: :error]
而我们之前说的,低于配置级别的日志参数不会求值也是前端的特性。因为它们都是宏,很容易实现这一点。一般情况下我们也是配置前端的日志级别,需要注意的就是配置的地方,不同地方配置的对象是不同的。
关于参数是否会求值,可以使用下面的示例:
Logger.info(IO.puts("evaluated!") && "hello world")
如果 :level
是 :info
及以下级别,可以同时看到 evaluated!
和 hello world
输出,而高于 :info
级别则什么也不会输出。
但是 :always_evaluate_messages
配置可以让参数总是被求值:
config :logger,
level: :error,
always_evaluate_messages: true
即便我们配置的日志级别高于 :info
, evaluated!
还是会被打印出来。这种情况下,即便是用函数作为日志的参数,也会被求值。
Logger.info(fn -> IO.puts("evaluated!") && "hello world" end)
我们还是能看到 evaluated!
被打印出来。所以正常情况下不会这样配置,让它保持默认就好。
需要注意的是 :always_evaluate_messages
只会影响到与7种级别对应的日志,换句话说,它只能影响到宏的行为。而 bare_log/3
是函数,不受 :always_evaluate_messages
的影响。对于 bare_log/3
而言,低于配置的级别的日志,只有在参数是匿名函数时,才不会被求值。因此在使用这类底层日志函数时,更推荐使用匿名函数,而不是表达式。
Logger.bare_log(:info, fn -> IO.puts("evaluated!") && "hello world" end)
当然更推荐的还是直接使用 info
这样的宏, bare_log/3
更多是用于需要动态控制日志级别的场景。
日志处理程序
前面我们说过,Elixir 的 Logger
应该是前后端分离的架构,客户端负责格式化和截断,具体的日志记录交给后端的日志处理程序。这样做的好处是当我们需要将日志记录到不同的地方时,只需要配置不同的后端就可以了。甚至我们可以同时将日志记录到多个后端,亦或是根据日志级别,将不同级别的日志记录到不同的文件中。而更神奇的时,日志处理程序居然还能在运行时动态添加!
:default_handler
其实就是用来配置 Erlang 的 logger
的,这部分配置完全可以参考 Erlang 的官方文档。支持以下配置:
id
- 自动设置module
- 自动设置level
- 日志等级filters
- 日志过滤器filter_default
- 所有日志过滤器都返回ignore
或没有日志过滤器时的日志行为,可以是log
或stop
,默认为log
formatter
- 日志格式config
- 配置日志处理器
注意这里的 level
和我们前面说的日志等级不是一个东西,这里配置的是日志后端的等级。
上面的 config
其实就是用来配置日志后端的,默认的后端处理程序是 Erlang 的 :logger_std_h
,默认是输出到控制台,也可以输出到文件,支持循环和自动压缩。比如我们可以通过以下配置将日志输出到文件:
config :logger, :default_handler,
config: [
file: ~c"system.log",
filesync_repeat_interval: 5000,
file_check: 5000,
max_no_bytes: 10_000_000,
max_no_files: 5,
compress_on_rotate: true
]
当然我们可以将它配置为 false
来禁用日志:
config :logger, default_handler: false
注意它只是关闭了后端的日志输出,前端该执行还是会执行的,比如参数求值。
logger_std_h
的官方文档可以戳👉这里👈查看,它支持以下参数:
type
- 指定日志记录的地方,可以是标准输出,标准错误,文件,以及io:device/0
,这就意味着甚至可以将日志输出到另一个节点!但它不能在运行时动态修改,默认是标准输出 ,如果配置了file
参数,则默认是文件。file
- 指定日志文件名称。不支持运行时动态修改,默认为文件名是处理器ID,在当前目录下。modes
- 指定打开日志文件的模式,不支持运行时动态修改,默认为[raw,append,delayed_write]
。日志文件总是 UTF-8 编码,不能修改。自定义指定模式时,会自动做一些调整,规则如下:- 没有
raw
则自动添加。 - 没有
write
,append
或exclusive
则自动添加append
。 - 没有
delayed_write
或{delayed_write, Size, Delay}
则自动添加delayed_write
。
- 没有
max_no_bytes
- 日志文件是否滚动,可以指定一个整数指定日志文件大小达到指定字节时滚动日志,默认未infinity
表示不滚动。max_no_files
- 滚动归档日志的保留数量,必须为非负整数,默认为 0。归档日志文件被命名为FileName.0
,FileName.1
,…FileName.N
。其中FileName
是日志文件名,FileName.0
是最新的归档,N
的最大值为max_no_files-1
。注意,设置为 0 不是关闭滚动,而是不会保留任何归档。compress_no_ratate
- 布尔值,指定滚动的归档日志是否应该被压缩,默认为false
。如果设置为true
,归档文件会通过gzip
压缩,且被命名为FileName.N.gz
。file_check
-logger_std_h
在每次写入日志之前,都会先读取文件信息。这是为了保证文件依然存在且和打开时具有相同的 inode。最然这会导致一些性能损失,但是可以保证日志文件被外部重命名或删除时,日志消息不会丢失。为了最小化性能损失,可以设置一个正整数 N,每隔 N 毫秒才去读取一次文件信息,但是日志事件丢失的风险也会随着 N 的增大而增加。默认为 0。filesync_repeat_interval
- 指定处理器将缓存数据同步到磁盘的时间间隔(毫秒)。虽然处理器会反复尝试同步,但只有在实际上有日志被记录时才会真正执行文件同步。如果设置为no_repeat
,会禁用文件同步,此时将由操作系统决定文件同步的频率,当然你也可以通过调用filesync/1
函数手动同步。默认是5000
毫秒。
logger_std_h
是 Erlang 的库,在 Erlang 中小写字母开头的都是原子,如果在 Elixir 中配置,记得原子要用 :
开头。
Logger
是封装的 Erlang 的 logger 模块,Elixir 会把 :default_handler
下的配置转成 map 后传递给 Erlang。
日志格式化
:default_formatter
用来配置日志的默认格式化程序,它配置的是日志的前端。它的值也是一个 keyword list,可以用来配置日志的格式,元数据,颜色,截断以及时间格式。
:format
- 配置日志格式。:metadata
- 配置元数据。:colors
- 配置日志的文本颜色与属性。:truncate
- 设置日志消息最大字节数,默认 8192 字节,超出被截断,并在末尾添加(truncated)
,可以通过:infinity
禁用截断。:utc_log
- 设置为true
时使用 UTC 时间,默认为false
,使用本地时间。
格式
日志格式通过 :format
键配置,是一个由占位参数构成的字符串,例如:
config :logger, :default_formatter,
format: "$time [$level] $message\n",
注意换行也要在格式字符串中指定,它并不会帮你自动换行。如果我们调用 Logger.info("Hello")
则会输出下面的内容:
18:43:12.439 [error] Hello
可以使用的占位参数如下:
$time
- 发送日志消息的时间$date
- 发送日志消息的日期$message
- 日志消息$level
- 日志级别$node
- 打印消息的节点$metadata
- 元数据,格式为"key=val key2=val2 "
注意时间中是不包含日期的,记录日期需要手动加上 $date
。
元数据
前面我们说过,日志函数支持传递一个可选的“元数据”参数。所谓“元数据”实际上就是一个 keyword list,或者理解为一个键值对列表。如果要在日志中记录元数据,需要做两件事:一是在格式字符串中加上 $metadata
参数,二是在 :default_formatter
下配置 :metadata
,这是一个列表,表示要在日志中记录哪些“元数据”,只有在 :metadata
中指定的元数据才会被记录。例如:
config :logger, :default_formatter,
format: "$time $metadata[$level] $message\n",
metadata: [:a, :b]
然后在日志函数中传入自定义的元数据: Logger.info("Hello", a: 1, b: 2)
,不出意外的话,我们可以看到如下输出:
18:37:14.921 a=1 b=2 [info] Hello
如果要打印全部元数据,可以使用 :all
,例如:
config :logger, :default_formatter,
format: "$time $metadata[$level] $message\n",
metadata: :all
元数据有一些默认值,它们会自动添加,不用我们手动传递:
:application
- 当前应用名称:mfa
- 当前模块、函数和元数:module
- 当前模块,来自:mfa
:function
- 当前函数及元数,来自:mfa
:file
- 当前文件:line
- 当前行:pid
- 当前进程PID:initial_call
- 启动进程的初始调用:registered_name
- 进程注册名,以原子形式表示:domain
- 消息来源。例如,所有 Elixir 日志默认设置为[:elixir]
。Erlang 日志可能是[:otp]
或[:sasl]
:crash_reason
- 一个包含两个元素的元组,表示进程退出原因
这些默认的元数据并不总是存在,比如调用 bare_log/3
时,默认的元数据只有 :pid
,而像 :initial_call
, :registered_name
和 crash_reason
明显只有在 GenServer 等这样的行为内才有。
颜色
日志颜色可以通过 :colors
来配置,也是一个 keyword list。它会给日志加上颜色标签,只有在支持颜色的终端才能看到效果,否则,比如输出到文件,只会多出一些不可打印字符。更多可以参考IO.ANSI。
:colors
keyword list 支持的配置如下:
:enabled
- 布尔值,允许打开和关闭着色。默认为:IO.ANSI.enabled?/0
:debug
-debug
消息的颜色。默认为::cyan
:info
-info
和notice
消息的颜色。默认为::normal
:warning
-warning
消息的颜色。默认为::yellow
:error
-error
及更高级别消息的颜色。默认为::red
如果默认没有颜色的话,那么就需要通过 :enabled
手动开启,然后就是确认你的终端确实支持颜色属性。
config :logger,
level: :info,
default_formatter: [
format: "$time $metadata[$level] $message\n",
colors: [enabled: true, info: :green]
]
需要注意的是,在配置文件中并不是每一种日志级别都能单独配置颜色, :info
就同时控制了 info
和 notice
的颜色, error
控制了4个级别的日志颜色。如果要更细致的控制每一种级别日志的颜色,可以在元数据中通过 :ansi_color
来控制,它的优先级要高于配置文件,当然前提是 :enabled
得开启。
Logger.notice("倒车请注意", ansi_color: :blue)
文本除了颜色,还有其他属性,比如下划线,删除线,高亮,闪烁等,我们可以通过列表来设置多个属性,比如我们让 warning
变成具有删除线的品红色文本:
config :logger,
level: :info,
default_formatter: [
format: "$time $metadata[$level] $message\n",
colors: [enabled: true, warning: [:crossed_out, :magenta]]
]
文本属性支持内置的预定义原子,如下表所示:
属性 | 含义 | 颜色 | 含义 |
---|---|---|---|
:normal | 默认文本样式 | :black | 黑色 |
:bright | 亮色文本 | :red | 红色 |
:faint | 淡色文本 | :green | 绿色 |
:italic | 斜体文本(需要终端支持) | :yellow | 黄色 |
:underline | 下划线文本 | :blue | 蓝色 |
:blink | 闪烁文本 | :magenta | 品红色 |
:reverse | 背景和前景颜色互换 | :cyan | 青色 |
:concealed | 隐藏文本 | :white | 白色 |
:crossed_out | 删除线文本 |
特殊的 :console
到目前位置,我们可以清晰看到日志配置的两大模块:日志处理程序和格式化。不同的功能分别在不同的模块下配置。
但是我们在 Phoenix 项目下还能看到 :console
这个配置。它出现的比较早,综合了许多功能,但是在 Elixir 1.15 版本之后被弃用,因此可以根据自己使用的 Elixir 版本进行选择,版本比较新的话,也是不建议再使用这个配置。
:console
支持以下配置:
:level
- 日志级别:format
- 日志格式:metadata
- 配置需要记录的元数据:colors
- 配置日志颜色:device
- 配置日志输出位置,可以指定为日志文件路径,但在 1.15 以上版本已不生效:max_buffer
- 未收到IO设备确认的最大消息缓冲数,缓冲区满以后,后端将会阻塞
对于日志级别,格式,元数据和颜色和我们之前将到的是一样的, :device
已经亲测无效了,所以在高版本中是无法通过 :console
配置将日志输出到文件的。
不常用配置
最后我们介绍下那些不常用的配置,一般情况下,我们极少会去修改它们。
:compile_time_application
用来在编译时设置“应用名”元数据,Mix 会自动设置它,自己在配置文件中设置其实也不会生效。
:compile_time_purge_matching
用来在编译时“剪除”满足指定条件的日志代码,虽然这样可以消除运行时开销,但是由于代码都被删除了,也就意味着动态调整日志级别时,只能向“上”调,向“下”调是无效的。
它的配置是一个 keyword list 的列表,列表中每个 keyword list 表示一个条件。它支持以下四种条件:
:level_lower_than
- 配置一个日志级别,低于该级别的日志会被剪除:module
- 指定需要剪除日志的模块:function
- 指定需要剪除日志的函数:application
- 指定需要剪除日志的应用
以上条件可以自由组合,条件之间的逻辑关系是“或”,也就是满足任何一个条件就会被剪除。例如:
config :logger,
compile_time_purge_matching: [
[application: :foo],
[module: Bar, function: "foo/3", level_lower_than: :error]
]
以上配置会剪除 :foo
应用和 Bar.foo/3
中低于 error
级别的日志。
:translator_inspect_opts
配置将 OTP 错误翻译成 Elixir 数据的行为。假设你有一个计数器的 GenServer:
defmodule Counter.Counter do
use GenServer
# client api
def start_link(opts) do
GenServer.start_link(__MODULE__, opts, name: __MODULE__)
end
def add(count) do
GenServer.cast(__MODULE__, {:add, count})
end
# server implamentation
def init(init_arg) do
{:ok, init_arg}
end
def handle_call(:get, _from, state) do
{:reply, state, state}
end
def handle_cast({:add, count}, state) do
{:noreply, state + count}
end
end
如果我们用 Counter.Counter.add("1")
会导致 GenServer 崩溃,在控制台可以看到崩溃消息打印:
iex(1)> Counter.Counter.start_link(1)
{:ok, #PID<0.156.0>}
iex(2)> Counter.Counter.add("1")
:ok
iex(3)> 14:59:09.996 [error] GenServer Counter.Counter terminating
** (ArithmeticError) bad argument in arithmetic expression
:erlang.+(1, "1")
(demo1 0.1.0) lib/counter/counter.ex:23: Counter.Counter.handle_cast/2
(stdlib 4.3) gen_server.erl:1123: :gen_server.try_dispatch/4
(stdlib 4.3) gen_server.erl:1200: :gen_server.handle_msg/6
(stdlib 4.3) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:"$gen_cast", {:add, "1"}}
:translator_inspect_opts
配置可以控制这个消息的格式,比如 :limit
可以控制最后一条消息的长度。这方面资料不多,基本上也很少去配置它。仅用来优化过大的 OTP 消息,但相比于此,解决 OTP 崩溃才更重要。
:handle_otp_reports
和 :handle_sasl_reports
都是布尔值,用来配置是否打印监督,崩溃和进程消息。
使用 mix new demo --sup
新建一个sup应用,默认情况下我们启动应用输出如下:
>iex -S mix
Compiling 1 file (.ex)
Generated demo1 app
Interactive Elixir (1.15.7) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)>
如果配置 handle_sasl_reports: :true
,再次启动应用,输出如下:
>iex -S mix
Compiling 1 file (.ex)
15:25:35.467 [info] Application logger started at :nonode@nohost
15:25:35.468 [info] Application demo started at :nonode@nohost
Interactive Elixir (1.15.7) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)>
可以看到多出了 logger
和 demo
两个应用的启动日志。