📜 ⬆️ ⬇️

Logging. "From the box"

Logging is used in every software product that has survived to the production stage. Erlang provides programmers with a complete ecosystem that includes application tracking mechanisms. In this part, I will consider exactly the functionality "out of the box."

0. How it works


Like other built-in utilities, logging is based on OTP principles.

Erlang error logger is an event manager (gen_event (3)), registered as error_logger. Events error, warning and info are sent from Erlang RTS and various applications in error_logger. By default, they are displayed in the console.

Initially, error_logger uses the simplest event handler that buffers and prints unprocessed event messages. During startup, the Kernel application replaces it with its event handler.
')
It is recommended in your applications to use error_logger to get universal reports. The user can add their own event handlers (add_report_handler / 1,2).

1. SASL


Every Erlang programmer knows what SASL is. Most tutorials are written using it. We will certainly enable SASL while debugging applications.

SASL displays a detailed report of various issues related to the work of supervisors and errors that occur.
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 includes 3 event handlers:

SASL supports specific configuration, which is detailed in the documentation. Installing the handler sasl_report_file_h and sasl_error_logger = {file, FileName} allows you to display information in a separate log file. However, when restarting the application, all old information will be deleted (!).

2. log_mf_h


log_mf_h is a gen_event handler that can be installed in any gen_event process. It saves all events to disk. Each event is saved in binary format. An application like the Report Browser (rb) can be used to read these logs.

log_mf_h: init / 3,4 return configuration arguments for gen_event: add_handler (EventMgr, log_mf_h, Args). They can be used in any event manager.

 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


As I wrote above, the SASL settings allow you to use log_mf_h for event handling. To do this, you need to specify similar parameters in the SASL configuration:
 [{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} ]}]. 


Now all events will be recorded in the specified directory. While your application is running, you can go into another shell and view (display the reports in a separate log (in readable form)) using the rb utility:
 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:~# 


four. ...


Here are described the tools that facilitate the development of the application, and allow the logging of simple systems. For large projects, there are a number of third-party applications that take advantage of Eralng (for example, distribution or a web interface), and provide the usual functionality of other platforms (for example, log level). But more about that next time.

Source: https://habr.com/ru/post/115209/


All Articles