从FTP模块学习先进的诊断技术(Erlang Trace机制)
April 12th, 2010
原创文章，转载请注明： 转载自系统技术非业余研究
本文链接地址: 从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.
昨天用了dbg，是很好用。在写代码时，就要更多的拆分成小函数，就能更好的用这个功能
遵循otp的习惯这些工具很无价。