otp
otp copied to clipboard
erlang
ftp:nlist returns `ok` which is unexpected
Describe the bug
Frequently, when calling ftp:nlist/2 a bare ok atom is returned, as opposed to a list result or error.
I reproduce it at 24.2 and I was also able to reproduce with OTP 24.3.2
Basically the same issue as described here https://github.com/erlang/otp/issues/4177
To Reproduce
Call multiple times :ftp.nlist(pid, path) it will return :ok atom
Expected behavior
Expected {:ok, result} or {:error, reason}
Affected versions 24.2 24.3.2 (latest)
Can you reproduce the problem with the following trace?
dbg:tracer(). dbg:p(all, [call]). dbg:tpl(ftp, handle_info, cx).
And share the result when the problem occurs?
@IngelaAndin sorry for late response. I'm using the elixir, hope it's okay:
:ftp.nlist(pid, String.to_charlist(path))
(<0.787.0>) call ftp:handle_info({tcp,#Port<0.25>,<<"227 Entering Passive Mode (172,19,0,6,117,49)\r\n">>},{state,{tcp,#Port<0.25>},
undefined,undefined,false,"/app",ftp_server_default,false,passive,
60000,<<>>,
{<<>>,[],start},
"226 0 matches total\r\n",<0.763.0>,
{<0.763.0>,#Ref<0.486019169.4142399489.57249>},
{setup_data_connection,{dir,"exports",short}},
inet,[],[],[],ignore,infinity,false,false,false}) ({gen_server,
try_dispatch,4})
(<0.787.0>) returned from ftp:handle_info/2 -> {noreply,
{state,
{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",
ftp_server_default,false,
passive,60000,<<>>,
{<<>>,[],start},
"227 Entering Passive Mode (172,19,0,6,117,49)\r\n",
<0.763.0>,
{<0.763.0>,
#Ref<0.486019169.4142399489.57249>},
{dir,"exports"},
inet,[],[],[],ignore,
infinity,false,false,false}}
:ok
(<0.787.0>) call ftp:handle_info({tcp,#Port<0.25>,
<<"150 Accepted data connection\r\n226 0 matches total\r\n">>},{state,{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",ftp_server_default,false,passive,60000,<<>>,
{<<>>,[],start},
"227 Entering Passive Mode (172,19,0,6,117,49)\r\n",<0.763.0>,
{<0.763.0>,#Ref<0.486019169.4142399489.57249>},
{dir,"exports"},
inet,[],[],[],ignore,infinity,false,false,false}) ({gen_server,
try_dispatch,4})
(<0.787.0>) returned from ftp:handle_info/2 -> {noreply,
{state,
{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",
ftp_server_default,false,
passive,60000,<<>>,
{<<"226 0 matches total\r\n">>,
[],start},
"150 Accepted data connection\r\n",
<0.763.0>,
{<0.763.0>,
#Ref<0.486019169.4142399489.57249>},
{handle_dir_result,"exports"},
inet,[],[],[],ignore,
infinity,false,false,false}}
(<0.787.0>) call ftp:handle_info({tcp_closed,#Port<0.38>},{state,{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",ftp_server_default,false,passive,60000,<<>>,
{<<"226 0 matches total\r\n">>,[],start},
"150 Accepted data connection\r\n",<0.763.0>,
{<0.763.0>,#Ref<0.486019169.4142399489.57249>},
{handle_dir_result,"exports"},
inet,[],[],[],ignore,infinity,false,false,false}) ({gen_server,
try_dispatch,4})
(<0.787.0>) call ftp:handle_info({tcp,#Port<0.25>,<<>>},{state,{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",ftp_server_default,false,passive,60000,<<>>,
{<<"226 0 matches total\r\n">>,[],start},
"150 Accepted data connection\r\n",<0.763.0>,
{<0.763.0>,#Ref<0.486019169.4142399489.57249>},
{handle_dir_result,"exports"},
inet,[],[],[],ignore,infinity,false,false,false}) ({ftp,
activate_ctrl_connection,
1})
(<0.787.0>) returned from ftp:handle_info/2 -> {noreply,
{state,
{tcp,#Port<0.25>},
{tcp,#Port<0.38>},
undefined,false,"/app",
ftp_server_default,false,
passive,60000,<<>>,
{<<>>,[],start},
"226 0 matches total\r\n",
<0.763.0>,undefined,
undefined,inet,[],[],[],
ignore,infinity,false,false,
false}}
(<0.787.0>) returned from ftp:handle_info/2 -> {noreply,
{state,
{tcp,#Port<0.25>},
undefined,undefined,false,
"/app",ftp_server_default,
false,passive,60000,<<>>,
{<<>>,[],start},
"226 0 matches total\r\n",
<0.763.0>,undefined,
{handle_dir_result,
"exports",<<>>},
inet,[],[],[],ignore,
infinity,false,false,false}}
It returns :ok in this call, instead of {:ok, []}. Let me know if you need a trace with successful case.
Hi, my turn to be sorry for the delay. The traces are Erlang even if the shell is Elixir so that is ok. I am suspecting some kind of race not handled correctly by the state machine. (This code is pretty old so it is a poor man's state machine implemented as a gen_server). Could you also trace the function handle_ctrl_result ?
dbg:tpl(ftp, handle_ctrl_result, cx).
For traceability, I will paste there the results that I get, which are consistent with @vermaxik . I will continue investigating.
ftp:nlist(Pid).
(<0.95.0>) call ftp:handle_ctrl_result({pos_compl," Entering Passive Mode (195,144,107,198,4,11).\r\n"},{state,{tcp,#Port<0.6>},
undefined,undefined,false,"/home/otp",ftp_server_default,
false,passive,60000,<<>>,
{<<>>,[],start},
"227 Entering Passive Mode (195,144,107,198,4,11).\r\n",<0.87.0>,
{<0.87.0>,#Ref<0.2839968628.2512125955.150205>},
{setup_data_connection,{dir,[],short}},
inet,[],[],[],ignore,infinity,false,false,false}) ({gen_server,
try_dispatch,4})
(<0.95.0>) returned from ftp:handle_ctrl_result/2 -> {noreply,
{state,
{tcp,#Port<0.6>},
{tcp,#Port<0.8>},
undefined,false,
"/home/otp",
ftp_server_default,
false,passive,60000,
<<>>,
{<<>>,[],start},
"227 Entering Passive Mode (195,144,107,198,4,11).\r\n",
<0.87.0>,
{<0.87.0>,
#Ref<0.2839968628.2512125955.150205>},
{dir,[]},
inet,[],[],[],ignore,
infinity,false,false,
false}}
(<0.95.0>) call ftp:handle_ctrl_result({pos_prel," Data connection already open; Transfer starting.\r\n"},{state,{tcp,#Port<0.6>},
{tcp,#Port<0.8>},
undefined,false,"/home/otp",ftp_server_default,false,
passive,60000,<<>>,
{<<"226 Transfer complete.\r\n">>,[],start},
"125 Data connection already open; Transfer starting.\r\n",<0.87.0>,
{<0.87.0>,#Ref<0.2839968628.2512125955.150205>},
{dir,[]},
inet,[],[],[],ignore,infinity,false,false,false}) ({gen_server,
try_dispatch,4})
(<0.95.0>) returned from ftp:handle_ctrl_result/2 -> {noreply,
{state,
{tcp,#Port<0.6>},
{tcp,#Port<0.8>},
undefined,false,
"/home/otp",
ftp_server_default,
false,passive,60000,
<<>>,
{<<"226 Transfer complete.\r\n">>,
[],start},
"125 Data connection already open; Transfer starting.\r\n",
<0.87.0>,
{<0.87.0>,
#Ref<0.2839968628.2512125955.150205>},
{handle_dir_result,[]},
inet,[],[],[],ignore,
infinity,false,false,
false}}
(<0.95.0>) call ftp:handle_ctrl_result({pos_compl," Transfer complete.\r\n"},{state,{tcp,#Port<0.6>},
{tcp,#Port<0.8>},
undefined,false,"/home/otp",ftp_server_default,false,
passive,60000,<<"pub\r\nreadme.txt\r\n">>,
{<<>>,[],start},
"226 Transfer complete.\r\n",<0.87.0>,
{<0.87.0>,#Ref<0.2839968628.2512125955.150205>},
{handle_dir_result,[]},
inet,[],[],[],ignore,infinity,false,false,false}) ({ftp,
activate_ctrl_connection,
1})
(<0.95.0>) returned from ftp:handle_ctrl_result/2 -> {noreply,
{state,
{tcp,#Port<0.6>},
{tcp,#Port<0.8>},
undefined,false,
"/home/otp",
ftp_server_default,
false,passive,60000,
<<"pub\r\nreadme.txt\r\n">>,
{<<>>,[],start},
"226 Transfer complete.\r\n",
<0.87.0>,undefined,
undefined,inet,[],[],
[],ignore,infinity,
false,false,false}}
ok
