从FTP模块学习先进的诊断技术(Erlang Trace机制)

来源:互联网 发布:淘宝知识产权处罚细则 编辑:程序博客网 时间:2024/04/28 19:38

从FTP模块学习先进的诊断技术(Erlang Trace机制)

 

我们开发好了一个软件的时候,通常是经过严格测试的,才分发给用户使用, 但是即使这样也不能保证用户的环境和我们的相同, 我们的软件还是会失败的. 问题是如何诊断这些问题.
通常的做法是写log,这是个很有效的方式. 但是写log要代码支持,而且会带来负面的性能影响. Erlang提供了强大的Trace机制, 帮助我们解决这个问题. OTP本身有很多模块利用了这个技术手段,我们从ftp模块学习下:

上代码:
lib/inets/src/ftp/ftp.erl

 771    %% Maybe activate dbg                                                                                                                                                                                   772    case key_search(debug, Options, disable) of 773        trace -> 774            dbg:tracer(), 775            dbg:p(all, [call]),  %% 我们关心函数调用 776            dbg:tpl(ftp, [{'_', [], [{return_trace}]}]), %%以及返回值 777            dbg:tpl(ftp_response, [{'_', [], [{return_trace}]}]), 778            dbg:tpl(ftp_progress, [{'_', [], [{return_trace}]}]); 779        debug -> 780            dbg:tracer(), 781            dbg:p(all, [call]), 782            dbg:tp(ftp, [{'_', [], [{return_trace}]}]), 783            dbg:tp(ftp_response, [{'_', [], [{return_trace}]}]), 784            dbg:tp(ftp_progress, [{'_', [], [{return_trace}]}]); 785        _ -> 786            %% Keep silent                                                                                                                                                                                  787            ok 788    end,

我们可以在启动参数里面加上debug标志, 在需要的时候打开这些诊断功能!

现在我们演示下,代码片段从inets userguide来的, 用户名密码不用试验了, 我不会告诉你的, 呵呵:

root@ubuntu:~# erlErlang R14A (erts-5.8) 1 [smp:2:2] [rq:2] [async-threads:0] [kernel-poll:false]Eshell V5.8  (abort with ^G)1> inets:start().  ok2> {ok,Pid} = inets:start(ftpc, [{host,"ftp.yufeng.info"},{debug,debug}])2> .(<0.45.0>) call ftp:handle_call({<0.31.0>, {open,ip_comm,       [{host,"ftp.yufeng.info"},        {progress,ignore},        {timeout,60000},        {ipfamily,inet},        {port,21},        {mode,passive}]}},{<0.31.0>,#Ref<0.0.0.45>},{state,undefined,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,undefined,undefined,inet,ignore})(<0.45.0>) call ftp_progress:start_link(ignore)(<0.45.0>) returned from ftp_progress:start_link/1 -> ignore(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.45>},                                                open,inet,ignore},                                               59493}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,     <<"220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.45>},       open,inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n"){ok,<0.45.0>}(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,                                                      "---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,undefined,undefined,                                                inet,ignore}}3> ftp:user(Pid, "username", "password").(<0.31.0>) call ftp:user(<0.45.0>,"username","password")(<0.45.0>) call ftp:handle_call({<0.31.0>,{user,"username","password"}},{<0.31.0>,#Ref<0.0.0.64>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,undefined,undefined,inet,ignore})(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.64>},                                                {handle_user,"password",[]},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"331 User yufengin OK. Password required\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.64>},       {handle_user,"password",[]},       inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"331 User yufengin OK. Password required\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "331 User yufengin OK. Password required\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("331 User yufengin OK. Password required\r\n")(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_interm,                                                      " User yufengin OK. Password required\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.64>},                                                {handle_user_passwd,[]},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,     <<"230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.64>},       {handle_user_passwd,[]},       inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n")ok(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,                                                      "-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,undefined,undefined,                                                inet,ignore}}(<0.31.0>) returned from ftp:user/3 -> ok4> 4>  ftp:pwd(Pid).(<0.31.0>) call ftp:pwd(<0.45.0>)(<0.45.0>) call ftp:handle_call({<0.31.0>,pwd},{<0.31.0>,#Ref<0.0.0.84>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,undefined,undefined,inet,ignore})(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.84>},                                                pwd,inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"257 \"/\" is your current location\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.84>},       pwd,inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"257 \"/\" is your current location\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "257 \"/\" is your current location\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("257 \"/\" is your current location\r\n"){ok,"/"}(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,                                                      " \"/\" is your current location\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,undefined,undefined,                                                inet,ignore}}(<0.31.0>) returned from ftp:pwd/1 -> {ok,"/"}7> ftp:recv(Pid, "favicon.ico").(<0.31.0>) call ftp:recv(<0.45.0>,"favicon.ico")(<0.45.0>) call ftp:handle_call({<0.31.0>,{recv,"favicon.ico","favicon.ico"}},{<0.31.0>,#Ref<0.0.0.120>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.112>},       undefined,inet,ignore})(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.120>},                                                {setup_data_connection,                                                 {recv_file,"favicon.ico",                                                  {file_descriptor,prim_file,                                                   {#Port<0.1087>,9}}}},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,     <<"227 Entering Passive Mode (74,220,215,202,156,59)\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,    passive,60000,<<>>,    {<<>>,[],start},    <0.31.0>,    {<0.31.0>,#Ref<0.0.0.120>},    {setup_data_connection,        {recv_file,"favicon.ico",            {file_descriptor,prim_file,{#Port<0.1087>,9}}}},    inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"227 Entering Passive Mode (74,220,215,202,156,59)\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "227 Entering Passive Mode (74,220,215,202,156,59)\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("227 Entering Passive Mode (74,220,215,202,156,59)\r\n")(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,                                                      " Entering Passive Mode (74,220,215,202,156,59)\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                #Port<0.1093>,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.120>},                                                {recv_file,                                                 {file_descriptor,prim_file,                                                  {#Port<0.1087>,9}}},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"150 Accepted data connection\r\n">>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,       passive,60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.120>},       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},       inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"150 Accepted data connection\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "150 Accepted data connection\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("150 Accepted data connection\r\n")(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_prel,                                                      " Accepted data connection\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                #Port<0.1093>,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.120>},                                                {recv_file,                                                 {file_descriptor,prim_file,                                                  {#Port<0.1087>,9}}},                                                inet,ignore}}ok8> (<0.45.0>) call ftp:handle_info({tcp,#Port<0.1093>,     <<71,73,70,56,57,97,1,0,1,0,128,0,0,255,255,255,255,255,255,33,249,4,1,7,       0,1,0,44,0,0,0,0,1,0,1,0,0,2,2,76,1,0,59>>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,       passive,60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.120>},       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},       inet,ignore})(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                #Port<0.1093>,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.120>},                                                {recv_file,                                                 {file_descriptor,prim_file,                                                  {#Port<0.1087>,9}}},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp_closed,#Port<0.1093>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,       passive,60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.120>},       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},       inet,ignore})(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,                                                {<0.31.0>,#Ref<0.0.0.120>},                                                {recv_file,                                                 {file_descriptor,prim_file,                                                  {#Port<0.1087>,9}}},                                                inet,ignore}}(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,     <<"226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,       {<0.31.0>,#Ref<0.0.0.120>},       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},       inet,ignore})(<0.45.0>) call ftp_response:parse_lines(<<"226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n">>,[],start)(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,                                                        "226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n",                                                        <<>>}(<0.45.0>) call ftp_response:interpret("226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n")(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,                                                      "-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n"}(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,                                               {state,#Port<0.1086>,                                                undefined,false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,undefined,undefined,                                                inet,ignore}}(<0.31.0>) returned from ftp:recv/2 -> ok8> inets:stop(ftpc, Pid).ok9> (<0.31.0>) call ftp:stop_service(<0.45.0>)(<0.31.0>) returned from ftp:stop_service/1 -> ok(<0.45.0>) call ftp:handle_cast({<0.31.0>,close},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,undefined,undefined,inet,ignore})(<0.45.0>) returned from ftp:handle_cast/2 -> {stop,normal,                                               {state,undefined,undefined,                                                false,"/root",                                                ftp_server_default,false,                                                passive,60000,<<>>,                                                {<<>>,[],start},                                                <0.31.0>,undefined,undefined,                                                inet,ignore}}(<0.45.0>) call ftp:terminate(normal,{state,undefined,undefined,false,"/root",ftp_server_default,false,passive,       60000,<<>>,       {<<>>,[],start},       <0.31.0>,undefined,undefined,inet,ignore})(<0.45.0>) returned from ftp:terminate/2 -> ok9> h().      1: inets:start()-> ok2: {ok,Pid} =       inets:start(ftpc, [{host,"ftp.yufeng.info"},{debug,debug}])-> {ok,<0.45.0>}3: ftp:user(Pid, "username", "password")-> ok4: ftp:pwd(Pid)-> {ok,"/"}5: ftp:cd(Pid, "public_html")-> ok6: ftp:lpwd(Pid)-> {ok,"/root"}7: ftp:recv(Pid, "favicon.ico")-> ok8: inets:stop(ftpc, Pid)-> ok

Bingo! 我们非常的清楚了看到了整个系统交互的流程. 不废吹灰之力.

原创粉丝点击