Как стать автором
Обновить

Logging. «Из коробки»

Время на прочтение 8 мин
Количество просмотров 6.1K
Ведение логов применяется в каждом программном продукте, дожившем до стадии продакшена. Erlang предоставляет программистам целую экосистему, которая включает и механизмы слежения за приложением. В этой части я рассмотрю именно функционал «из коробки».

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). Но об этом в следующий раз.
Теги:
Хабы:
+22
Комментарии 5
Комментарии Комментарии 5

Публикации

Истории

Ближайшие события

Московский туристический хакатон
Дата 23 марта – 7 апреля
Место
Москва Онлайн
Геймтон «DatsEdenSpace» от DatsTeam
Дата 5 – 6 апреля
Время 17:00 – 20:00
Место
Онлайн