Ведение логов применяется в каждом программном продукте, дожившем до стадии продакшена. Erlang предоставляет программистам целую экосистему, которая включает и механизмы слежения за приложением. В этой части я рассмотрю именно функционал «из коробки».
Как и другие встроенные утилиты, логгирование построено по принципах OTP.
Erlang error logger – это менеджер эвентов (gen_event (3)), зарегистрированный как error_logger. События error, warning и info посылаются от Erlang RTS и различных приложений в error_logger. По умолчанию, они выводятся в консоль.
Первоначально, error_logger использует наиболее простой обработчик событий, который буферизует и печатает необработанные сообщения о событиях. Во время запуска приложение Kernel заменяет его своим обработчиком событий.
Рекомендуется в своих приложениях использовать error_logger для получения универсальных отчетов. Пользователь может добавить свои собственные обработчики событий (add_report_handler/1,2).
Каждый программист на Erlang знает, что такое SASL. Большинство туториалов написаны с его использованием. Мы непременно включаем SASL во время отладки приложений.
SASL выводит подробный отчет различных собитый, связанных с работой супервизоров и возникающих ошибках.
SASL включает 3 обработчика событий (event handler):
SASL поддерживает определенное конфигурирование, которое подробно описано в документации. Установка обработчика sasl_report_file_h и sasl_error_logger = {file, FileName} позволит выводить информацию в отдельный лог-файл. Однако при рестарте приложения вся старая информация будет удалена (!).
log_mf_h — это gen_event handler, который можно установить в любой gen_event процесс. Он сохраняет на диск все события. Каждое событие сохраняется в бинарном формате. Приложение наподобие Report Browser (rb) может быть использовано для чтения этих логов.
log_mf_h:init/3,4 возвращают аргументы конфигурации для gen_event:add_handler(EventMgr, log_mf_h, Args). Их можно использовать в любом менеджере событий.
Как я выше писал, настройки SASL позволяют использовать log_mf_h для обработки событий. Для этого в конфигурации SASL нужно указать подобные параметры:
Теперь все события будут записаны в указанную директорию. Пока ваше приложение работает, выможете зайти в другую оболочку и росмотреть (вывести отчеты в отдельный лог (в читаемом виде)) с помощью утилиты rb:
Здесь описаны инструменты, которые облегчают разработку приложения, и позволяют вести логгирование несложных систем. Для крупных проектов существует ряд сторонних приложений, которые используют преимущества Eralng (например, распределенность или веб-интерфейс), так и предоставляют привычный функционал других платформ (например, log level). Но об этом в следующий раз.
0. Как это работает
Как и другие встроенные утилиты, логгирование построено по принципах OTP.
Erlang error logger – это менеджер эвентов (gen_event (3)), зарегистрированный как error_logger. События error, warning и info посылаются от Erlang RTS и различных приложений в error_logger. По умолчанию, они выводятся в консоль.
Первоначально, error_logger использует наиболее простой обработчик событий, который буферизует и печатает необработанные сообщения о событиях. Во время запуска приложение Kernel заменяет его своим обработчиком событий.
Рекомендуется в своих приложениях использовать error_logger для получения универсальных отчетов. Пользователь может добавить свои собственные обработчики событий (add_report_handler/1,2).
1. SASL
Каждый программист на Erlang знает, что такое SASL. Большинство туториалов написаны с его использованием. Мы непременно включаем SASL во время отладки приложений.
SASL выводит подробный отчет различных собитый, связанных с работой супервизоров и возникающих ошибках.
root@37221-1:~# erl -boot start_sasl
Erlang R13B03 (erts-5.7.4) [source] [rq:1] [async-threads:0] [hipe] [kernel-poll:false]
=PROGRESS REPORT==== 11-Mar-2011::19:34:39 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.35.0>},
{name,alarm_handler},
{mfa,{alarm_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:34:39 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.36.0>},
{name,overload},
{mfa,{overload,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:34:39 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.34.0>},
{name,sasl_safe_sup},
{mfa,
{supervisor,start_link,
[{local,sasl_safe_sup},sasl,safe]}},
{restart_type,permanent},
{shutdown,infinity},
{child_type,supervisor}]
=PROGRESS REPORT==== 11-Mar-2011::19:34:39 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.37.0>},
{name,release_handler},
{mfa,{release_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:34:39 ===
application: sasl
started_at: nonode@nohost
Eshell V5.7.4 (abort with ^G)
1> application:start(crypto).
=PROGRESS REPORT==== 11-Mar-2011::19:34:54 ===
supervisor: {local,crypto_sup}
started: [{pid,<0.49.0>},
{name,crypto_server},
{mfa,{crypto_server,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:34:54 ===
application: crypto
started_at: nonode@nohost
ok
2> rb:start().
{error,{"cannot locate report directory",
{child,undefined,rb_server,
{rb,start_link,[[]]},
temporary,brutal_kill,worker,
[rb]}}}
3>
=CRASH REPORT==== 11-Mar-2011::19:35:16 ===
crasher:
initial call: rb:init/1
pid: <0.51.0>
registered_name: []
exception exit: "cannot locate report directory"
in function gen_server:init_it/6
ancestors: [sasl_sup,<0.32.0>]
messages: []
links: [<0.33.0>]
dictionary: []
trap_exit: true
status: running
heap_size: 233
stack_size: 24
reductions: 109
neighbours:
SASL включает 3 обработчика событий (event handler):
- sasl_report_tty_h — supervisor reports, crash reports и progress выводятся в консоль.
- sasl_report_file_h — supervisor reports, crash report и progress выводятся в отдельный файл.
- error_logger_mf_h — этот логгер обрабатывает все события. Он устанавливает обработчик событий log_mf_h (подробнее ниже) в error_logger.
SASL поддерживает определенное конфигурирование, которое подробно описано в документации. Установка обработчика sasl_report_file_h и sasl_error_logger = {file, FileName} позволит выводить информацию в отдельный лог-файл. Однако при рестарте приложения вся старая информация будет удалена (!).
2. log_mf_h
log_mf_h — это gen_event handler, который можно установить в любой gen_event процесс. Он сохраняет на диск все события. Каждое событие сохраняется в бинарном формате. Приложение наподобие Report Browser (rb) может быть использовано для чтения этих логов.
log_mf_h:init/3,4 возвращают аргументы конфигурации для gen_event:add_handler(EventMgr, log_mf_h, Args). Их можно использовать в любом менеджере событий.
root@37221-1:/home/user# erl -boot start_sasl
Erlang R13B03 (erts-5.7.4) [source] [rq:1] [async-threads:0] [hipe] [kernel-poll:false]
=PROGRESS REPORT==== 11-Mar-2011::19:48:22 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.35.0>},
{name,alarm_handler},
{mfa,{alarm_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:48:22 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.36.0>},
{name,overload},
{mfa,{overload,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:48:22 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.34.0>},
{name,sasl_safe_sup},
{mfa,
{supervisor,start_link,
[{local,sasl_safe_sup},sasl,safe]}},
{restart_type,permanent},
{shutdown,infinity},
{child_type,supervisor}]
=PROGRESS REPORT==== 11-Mar-2011::19:48:22 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.37.0>},
{name,release_handler},
{mfa,{release_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:48:22 ===
application: sasl
started_at: nonode@nohost
Eshell V5.7.4 (abort with ^G)
1> Conf = log_mf_h:init(".", 1024, 10).
{".",1024,10,#Fun<log_mf_h.0.56828844>}
2> gen_event:add_handler(error_logger, log_mf_h, Conf).
ok
3> F = fun(N) -> N() end.
#Fun<erl_eval.6.13229925>
4> spawn(F).
=ERROR REPORT==== 11-Mar-2011::19:49:59 ===
Error in process <0.48.0> with exit value: {{badarity,{#Fun<erl_eval.6.13229925>,[]}},[{erlang,apply,2}]}
<0.48.0>
5> application:start(crypto).
=PROGRESS REPORT==== 11-Mar-2011::19:50:29 ===
supervisor: {local,crypto_sup}
started: [{pid,<0.54.0>},
{name,crypto_server},
{mfa,{crypto_server,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::19:50:29 ===
application: crypto
started_at: nonode@nohost
ok
6> rb:start([{report_dir, "."}]).
rb: reading report...done.
=PROGRESS REPORT==== 11-Mar-2011::19:50:53 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.56.0>},
{name,rb_server},
{mfa,{rb,start_link,[[{report_dir,"."}]]}},
{restart_type,temporary},
{shutdown,brutal_kill},
{child_type,worker}]
{ok,<0.56.0>}
7> rb:list().
No Type Process Date Time
== ==== ======= ==== ====
3 error <0.25.0> 2011-03-11 19:49:59
2 progress <0.51.0> 2011-03-11 19:50:29
1 progress <0.24.0> 2011-03-11 19:50:29
ok
8> rb:list(error).
No Type Process Date Time
== ==== ======= ==== ====
3 error <0.25.0> 2011-03-11 19:49:59
ok
9> rb:show(3).
ERROR REPORT emulator 2011-03-11 19:49:59
===============================================================================
Error in process <0.48.0> with exit value: {{badarity,{#Fun<erl_eval.6.13229925>,[]}},[{erlang,apply,2}]}
ok
10> halt().
root@37221-1:/home/user# ls -1
1
2
index
mboga
root@37221-1:/home/user#
3. SASL + log_mf_h
Как я выше писал, настройки SASL позволяют использовать log_mf_h для обработки событий. Для этого в конфигурации SASL нужно указать подобные параметры:
[{sasl, [
{sasl_error_logger, false},
{error_logger_mf_dir, "/home/user/mboga/log/log_mf_h"},
{error_logger_mf_maxbytes, 1024},
{error_logger_mf_maxfiles, 10}
]}].
Теперь все события будут записаны в указанную директорию. Пока ваше приложение работает, выможете зайти в другую оболочку и росмотреть (вывести отчеты в отдельный лог (в читаемом виде)) с помощью утилиты rb:
root@37221-1:~# ps aux | grep erlang
root 27943 0.0 0.1 1980 368 ? S Mar08 0:01 /usr/lib/erlang/erts-5.7.4/bin/epmd -daemon
root 31714 0.5 3.0 13912 8092 ? S 07:37 3:45 /usr/lib/erlang/erts-5.7.4/bin/beam -- -root /usr/lib/erlang -progname erl -- -home /root -- -noshell -pa ebin edit deps/erldis/ebin deps/mochiweb/ebin -boot logging -sname mboga_web_dev -s mboga_web -s reloader
root 31944 0.0 0.2 1888 700 pts/1 S+ 20:05 0:00 grep --color=auto erlang
root@37221-1:~# erl -boot start_sasl
Erlang R13B03 (erts-5.7.4) [source] [rq:1] [async-threads:0] [hipe] [kernel-poll:false]
=PROGRESS REPORT==== 11-Mar-2011::20:05:43 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.35.0>},
{name,alarm_handler},
{mfa,{alarm_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::20:05:43 ===
supervisor: {local,sasl_safe_sup}
started: [{pid,<0.36.0>},
{name,overload},
{mfa,{overload,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::20:05:43 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.34.0>},
{name,sasl_safe_sup},
{mfa,
{supervisor,start_link,
[{local,sasl_safe_sup},sasl,safe]}},
{restart_type,permanent},
{shutdown,infinity},
{child_type,supervisor}]
=PROGRESS REPORT==== 11-Mar-2011::20:05:43 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.37.0>},
{name,release_handler},
{mfa,{release_handler,start_link,[]}},
{restart_type,permanent},
{shutdown,2000},
{child_type,worker}]
=PROGRESS REPORT==== 11-Mar-2011::20:05:43 ===
application: sasl
started_at: nonode@nohost
Eshell V5.7.4 (abort with ^G)
1> rb:start([{report_dir, "/home/user/mboga/log/log_mf_h"}]).
rb: reading report...done.
rb: reading report...done.
rb: reading report...done.
rb: reading report...done.
rb: reading report...done.
rb: reading report...done.
=PROGRESS REPORT==== 11-Mar-2011::20:07:02 ===
supervisor: {local,sasl_sup}
started: [{pid,<0.47.0>},
{name,rb_server},
{mfa,
{rb,start_link,
[[{report_dir,
"/home/user/mboga/log/log_mf_h"}]]}},
{restart_type,temporary},
{shutdown,brutal_kill},
{child_type,worker}]
{ok,<0.47.0>}
2> rb:start_log("/home/user/mboga/log/rb.log").
ok
3> rb:list().
No Type Process Date Time
== ==== ======= ==== ====
...
29 progress <6800.8.0> 2011-03-10 23:00:44
28 error_report <6800.50.0> 2011-03-10 23:01:10
27 error_report <6800.50.0> 2011-03-10 23:01:10
26 error_report <6800.50.0> 2011-03-10 23:01:11
25 progress <6800.34.0> 2011-03-10 23:02:52
24 progress <6800.34.0> 2011-03-10 23:02:52
...
4 progress <6800.50.0> 2011-03-11 07:37:50
3 progress <6800.29.0> 2011-03-11 07:37:50
2 progress <6800.8.0> 2011-03-11 07:37:50
1 crash_report mochiweb_acceptor 2011-03-11 10:08:03
ok
4> rb:list(crash_report).
No Type Process Date Time
== ==== ======= ==== ====
48 crash_report mochiweb_acceptor 2011-03-10 15:29:26
44 crash_report supervisor_bridge 2011-03-10 22:46:40
41 crash_report reloader 2011-03-10 22:55:04
1 crash_report mochiweb_acceptor 2011-03-11 10:08:03
ok
5> rb:show(1).
ok
6> rb:list(error_report).
No Type Process Date Time
== ==== ======= ==== ====
47 error_report <6800.50.0> 2011-03-10 22:46:40
28 error_report <6800.50.0> 2011-03-10 23:01:10
27 error_report <6800.50.0> 2011-03-10 23:01:10
26 error_report <6800.50.0> 2011-03-10 23:01:11
ok
7> rb:show(27).
ok
8> rb:stop().
ok
root@37221-1:~# cat /home/user/mboga/log/rb.log
CRASH REPORT <6768.60.0> 2011-03-11 10:08:03
===============================================================================
Crashing process
initial_call
{mochiweb_acceptor,init,['Argument__1','Argument__2','Argument__3']}
pid <6768.60.0>
registered_name []
error_info
{error,function_clause,
[{mochiweb,new_request,
[{#Port<6768.1465>,
{"CONNECT",{scheme,"www.google.com","443"},{1,0}},
[]}]},
{mochiweb_http,headers,5},
{proc_lib,init_p_do_apply,3}]}
ancestors [mboga_web_web,mboga_web_sup,<6768.51.0>]
messages []
links [<6768.56.0>,#Port<6768.1465>]
dictionary []
trap_exit false
status running
heap_size 2584
stack_size 24
reductions 59064
ERROR REPORT <6768.75.0> 2011-03-10 23:01:10
===============================================================================
"web request failed"
path upload/
type exit
what could_not_open_file_for_writing
trace
[{mboga_web_web,callback,2},
{mochiweb_multipart,feed_mp,2},
{mboga_web_web,upload,2},
{mboga_web_web,loop,3},
{mochiweb_http,headers,5},
{proc_lib,init_p_do_apply,3}]
root@37221-1:~#
4. ...
Здесь описаны инструменты, которые облегчают разработку приложения, и позволяют вести логгирование несложных систем. Для крупных проектов существует ряд сторонних приложений, которые используют преимущества Eralng (например, распределенность или веб-интерфейс), так и предоставляют привычный функционал других платформ (например, log level). Но об этом в следующий раз.