从FTP模块学习先进的诊断技术(Erlang Trace机制)
原创文章,转载请注明: 转载自系统技术非业余研究
本文链接地址: 从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:~# erl Erlang R14A (erts-5.8) [source] [smp:2:2] [rq:2] [async-threads:0] [kernel-poll:false] Eshell V5.8 (abort with ^G) 1> inets:start(). ok 2> {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 -> ok 4> 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}} ok 8> (<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 -> ok 8> inets:stop(ftpc, Pid). ok 9> (<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 -> ok 9> h(). 1: inets:start() -> ok 2: {ok,Pid} = inets:start(ftpc, [{host,"ftp.yufeng.info"},{debug,debug}]) -> {ok,<0.45.0>} 3: ftp:user(Pid, "username", "password") -> ok 4: ftp:pwd(Pid) -> {ok,"/"} 5: ftp:cd(Pid, "public_html") -> ok 6: ftp:lpwd(Pid) -> {ok,"/root"} 7: ftp:recv(Pid, "favicon.ico") -> ok 8: inets:stop(ftpc, Pid) -> ok
Bingo! 我们非常的清楚了看到了整个系统交互的流程. 不废吹灰之力.
Post Footer automatically generated by wp-posturl plugin for wordpress.
Recent Comments