OTP 22 中的 TLS 日志改进
2018 年 10 月 05 日 · 作者：Péter Dimitrov
Erlang/OTP 22 对于 ssl 应用来说将是一个重要的版本。我们正在开发一些新特性和改进，例如对 TLS 1.3 的支持，其中一些已经在主分支上了。这篇博文介绍了基于新的 logger API 构建的新 ssl 调试日志。
用法 #
随着 ssl 应用经历大量更改，新的 logger API 的发布为提升其调试日志功能提供了机会，使其与 OpenSSL 保持一致。
我们引入了一个新的选项 log_level，用于指定 ssl 应用的日志级别。它可以取以下值（按详细程度递增排序）：emergency、alert、critical、error、warning、notice、info 和 debug。在详细级别为 notice 及以上时，TLS 中会显示错误报告。级别 debug 会触发 TLS 协议消息的详细日志记录，其风格与 OpenSSL 类似。
可以通过两个简单的步骤开启详细的调试日志：log_level 应设置为 debug，并且应配置 logger 以启用 ssl 应用的 debug 日志记录。以下代码片段是一个简单的 TLS 服务器和客户端示例模块
-module(ssltest).
-compile(export_all).
-define(PORT, 11000).
server() ->
application:load(ssl),
logger:set_application_level(ssl, debug),
{ok, _} = application:ensure_all_started(ssl),
Port = ?PORT,
LOpts = [{certfile, "server.pem"},
{keyfile, "server.key"},
{versions, ['tlsv1.2']},
{log_level, debug}
],
{ok, LSock} = ssl:listen(Port, LOpts),
{ok, CSock} = ssl:transport_accept(LSock),
{ok, _} = ssl:handshake(CSock).
client() ->
application:load(ssl),
logger:set_application_level(ssl, debug),
{ok, _} = application:ensure_all_started(ssl),
Port = ?PORT,
COpts = [{verify, verify_peer},
{cacertfile, "ca.pem"},
{versions, ['tlsv1.2']},
{log_level, debug}
],
{ok, Sock} = ssl:connect("localhost", Port, COpts).
在各自的 Erlang shell 中启动服务器和客户端会产生以下 TLS 协议消息的详细日志
1> ssltest:server().
reading (238 bytes) TLS 1.2 Record Protocol, handshake
0000 - 16 03 03 00 e9 01 00 00 e5 03 03 5b ab 42 7a ee ...........[.Bz.
0010 - 91 23 df 70 30 fb 41 b9 c5 14 79 d7 02 48 74 c9 .#.p0.A...y..Ht.
0020 - b9 a9 8f e0 e9 04 1a f9 a8 21 49 00 00 4a 00 ff .........!I..J..
0030 - c0 2c c0 30 c0 24 c0 28 c0 2e c0 32 c0 26 c0 2a .,.0.$.(...2.&.*
0040 - 00 9f 00 a3 00 6b 00 6a c0 2b c0 2f c0 23 c0 27 .....k.j.+./.#.'
0050 - c0 2d c0 31 c0 25 c0 29 00 9e 00 a2 00 67 00 40 .-.1.%.).....g.@
0060 - c0 0a c0 14 00 39 00 38 c0 05 c0 0f c0 09 c0 13 .....9.8........
0070 - 00 33 00 32 c0 04 c0 0e 01 00 00 72 00 00 00 0e .3.2.......r....
0080 - 00 0c 00 00 09 6c 6f 63 61 6c 68 6f 73 74 00 0a .....localhost..
0090 - 00 3a 00 38 00 0e 00 0d 00 19 00 1c 00 0b 00 0c .:.8............
00a0 - 00 1b 00 18 00 09 00 0a 00 1a 00 16 00 17 00 08 ................
00b0 - 00 06 00 07 00 14 00 15 00 04 00 05 00 12 00 13 ................
00c0 - 00 01 00 02 00 03 00 0f 00 10 00 11 00 0b 00 02 ................
00d0 - 01 00 00 0d 00 18 00 16 06 03 06 01 05 03 05 01 ................
00e0 - 04 03 04 01 03 03 03 01 02 03 02 01 02 02 ..............
<<< TLS 1.2 Handshake, ClientHello
[{client_version,{3,3}},
{random,
<<91,171,66,122,238,145,35,223,112,48,251,65,185,197,20,121,215,2,72,116,
201,185,169,143,224,233,4,26,249,168,33,73>>},
{session_id,<<>>},
{cipher_suites,
[<<0,255>>,
<<"À,">>,<<"À0">>,<<"À$">>,<<"À(">>,<<"À.">>,<<"À2">>,<<"À&">>,<<"À*">>,
<<0,159>>,
<<0,163>>,
<<0,107>>,
<<0,106>>,
<<"À+">>,<<"À/">>,<<"À#">>,<<"À'">>,<<"À-">>,<<"À1">>,<<"À%">>,<<"À)">>,
<<0,158>>,
<<0,162>>,
<<0,103>>,
<<0,64>>,
<<"À\n">>,
<<192,20>>,
<<0,57>>,
<<0,56>>,
<<192,5>>,
<<192,15>>,
<<"À\t">>,
<<192,19>>,
<<0,51>>,
<<0,50>>,
<<192,4>>,
<<192,14>>]},
{compression_methods,[0]},
...
[Truncated for brevity]
这不是最终格式，因为还有很多方法可以进一步改进握手协议消息的表示，例如将密码套件转换为人类可读的 Erlang 表示形式。
作为比较，这是当同一个 Erlang 客户端连接到 OpenSSL 服务器时，来自 OpenSSL 服务器的调试输出
$ /usr/bin/openssl s_server -accept 11000 -tls1_2 -cert server.pem -key server.key -msg -debug
Using default temp DH parameters
ACCEPT
read from 0x16f0040 [0x16f56b3] (5 bytes => 5 (0x5))
0000 - 16 03 03 00 a1 .....
<<< ??? [length 0005]
16 03 03 00 a1
read from 0x16f0040 [0x16f56b8] (161 bytes => 161 (0xA1))
0000 - 01 00 00 9d 03 03 5b ac-a1 cc 20 4c 4d 52 d0 d4 ......[... LMR..
0010 - c8 fc dd 95 b0 fa 65 97-57 9e 44 aa dd 0e 46 10 ......e.W.D...F.
0020 - 6c 14 57 9c ce a0 00 00-04 00 ff c0 14 01 00 00 l.W.............
0030 - 70 00 2b 00 06 00 04 03-04 03 03 00 00 00 0e 00 p.+.............
0040 - 0c 00 00 09 6c 6f 63 61-6c 68 6f 73 74 00 0a 00 ....localhost...
0050 - 3a 00 38 00 0e 00 0d 00-19 00 1c 00 0b 00 0c 00 :.8.............
0060 - 1b 00 18 00 09 00 0a 00-1a 00 16 00 17 00 08 00 ................
0070 - 06 00 07 00 14 00 15 00-04 00 05 00 12 00 13 00 ................
0080 - 01 00 02 00 03 00 0f 00-10 00 11 00 0b 00 02 01 ................
0090 - 00 00 32 00 04 00 02 02-03 00 0d 00 04 00 02 02 ..2.............
00a0 - 01 .
<<< TLS 1.2 Handshake [length 00a1], ClientHello
01 00 00 9d 03 03 5b ac a1 cc 20 4c 4d 52 d0 d4
c8 fc dd 95 b0 fa 65 97 57 9e 44 aa dd 0e 46 10
6c 14 57 9c ce a0 00 00 04 00 ff c0 14 01 00 00
70 00 2b 00 06 00 04 03 04 03 03 00 00 00 0e 00
0c 00 00 09 6c 6f 63 61 6c 68 6f 73 74 00 0a 00
3a 00 38 00 0e 00 0d 00 19 00 1c 00 0b 00 0c 00
1b 00 18 00 09 00 0a 00 1a 00 16 00 17 00 08 00
06 00 07 00 14 00 15 00 04 00 05 00 12 00 13 00
01 00 02 00 03 00 0f 00 10 00 11 00 0b 00 02 01
00 00 32 00 04 00 02 02 03 00 0d 00 04 00 02 02
01
...
[Truncated for brevity]
事实证明，详细的调试日志在开发新扩展时特别有用，因为之前我们必须使用 wireshark 捕获来验证 TLS 协议消息。
实现 #
在 ssl 应用中，我们需要一种方法来处理两种类型的协议消息：tls_record 和 handshake，每种都有自定义的格式化程序。
最直接的解决方案是向 logger 添加一个新的处理程序实例，该实例具有特殊的格式化函数，可以过滤掉来自系统其他模块的所有“噪声”。
处理程序本身可以重用 logger 的标准处理程序 logger_std_h，因为它可以将日志打印到 standard_io。如果您的应用程序需要，您可以向 logger 添加多个标准处理程序实例。
logger:add_handler(ssl_handler, logger_std_h, Config),
新的 ssl_handler 配置了由 ssl_logger 模块实现的格式化程序。
Config = #{level => debug,
filter_default => stop,
formatter => {ssl_logger, #{}}},
处理程序过滤器级别设置为 debug，默认过滤器动作为 stop。我们还需要一个过滤器，如果日志事件的来源是 ssl 应用，则该过滤器将允许日志事件传递到格式化程序。换句话说，我们需要一个域过滤器，对所有与 [otp,ssl] 匹配的子域执行 log 操作。
Filter = {fun logger_filters:domain/2,{log,sub,[otp,ssl]}},
将所有内容放在一起，我们得到以下函数。
start_logger() ->
Config = #{level => debug,
filter_default => stop,
formatter => {ssl_logger, #{}}},
Filter = {fun logger_filters:domain/2,{log,sub,[otp,ssl]}},
logger:add_handler(ssl_handler, logger_std_h, Config),
logger:add_handler_filter(ssl_handler, filter_non_ssl, Filter).
当事件通过所有过滤器时，在 ssl_logger 中调用函数 format
format(#{level:= _Level, msg:= {report, Msg}, meta:= _Meta},
_Config0) ->
#{direction := Direction,
protocol := Protocol,
message := BinMsg0} = Msg,
case Protocol of
'tls_record' ->
BinMsg = lists:flatten(BinMsg0),
format_tls_record(Direction, BinMsg);
'handshake' ->
format_handshake(Direction, BinMsg0);
_Other ->
[]
end.
还有两个辅助函数封装了日志宏。添加它们是为了能够为每个 TLS 会话设置日志级别。
debug(Level, Report, Meta) ->
case logger:compare_levels(Level, debug) of
lt ->
?LOG_DEBUG(Report, Meta);
eq ->
?LOG_DEBUG(Report, Meta);
_ ->
ok
end.
notice(Level, Report) ->
case logger:compare_levels(Level, notice) of
lt ->
?LOG_NOTICE(Report);
eq ->
?LOG_NOTICE(Report);
_ ->
ok
end.
要打印日志事件，请使用配置的 ssl 日志级别和域参数调用上述函数。
ssl_logger:debug(Opts#ssl_options.log_level,
Report,
#{domain => [otp,ssl,handshake]}),
那些对当前开发状态感兴趣的人可以已经在 versions 选项中使用 'tlsv1.3' 原子。