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

    Ведение логов применяется в каждом программном продукте, дожившем до стадии продакшена. 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
    • 4,8k
    • 5
    Поделиться публикацией

    Похожие публикации

    Комментарии 5

      0
      Спасибо за хорошую статью. Но не описано, на мой взгляд, главное, над чем я сейчас бьюсь – как включить логирование всех ошибок в приложении в консоль во время отладки. У меня просто обычным методом они все не ловятся, т.к. появляются в spawn процессах.
        0
        с вопросом кстати разобрался) Теперь использую eunit.
          0
          Способ очень прост: не использовать процессы вне supervision tree. Забудьте про spawn.
          0
          Самый главный вопрос. Где править конфиг SASL? Конкретно файл. sasl.app не помогает.
          Есть например myapplication.app можно ли внутри как-то задать конфиг для sasl? Все перепробовал он упорно работает только с дефолтным конифигом неизвестно откуда его подгружая.
            0
            Просто, если кому-нибудь еще понадобится.
            Чтобы в срочном порядке заткнуть логгер на уже живой ноде — надо там выполнить
            [gen_event:delete_handler(X,Y,undefined) || X<-[error_logger], Y<-gen_event:which_handlers(X)].

            (подключиться к ноде можно через remsh, или в скрине, или если прямо сейчас в консоль оно валит).

            Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

            Самое читаемое