MLSD error - need help debugging root cause

[najevi]

Summary: MLSD command seems to return a corrupt set of subdirectories for just one of several directories at the root of the remote server. Perhaps as a result, navigating that remote directory tree is problematic.

FileZilla Client
----------------

Version: 3.48.0

Build information:
Compiled for: x86_64-w64-mingw32
Compiled on: x86_64-pc-linux-gnu
Build date: 2020-04-27
Compiled with: x86_64-w64-mingw32-gcc (GCC) 8.3-win32 20190406
Compiler flags: -g -O2 -Wall

Linked against:
wxWidgets: 3.0.5
SQLite: 3.31.1
GnuTLS: 3.6.12

Operating system:
Name: Windows 10 (build 18362), 64-bit edition
Version: 10.0
Platform: 64-bit system
CPU features: sse sse2 sse3 ssse3 sse4.1 sse4.2 avx aes pclmulqdq rdrnd lm
Settings dir: C:\Users\Chris\AppData\Roaming\FileZilla\

= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =

Remote FTP server:
Motorola File Manager v5.0.05 (Apache FtpServer Parent version 1.0.6)
running on
Moto x4 (Android 9)

= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =

Server (smartphone) and client (laptop) are on a wireless LAN.

There is one root level directory (/Pictures) on the server that has bogus subdirectories when viewed in the remote pane of FileZilla.

The alphabetically first subdirectory is /Pictures/LINE .. and FileZilla works perfectly well downloading all files within that folder to a local directory on the Win_10 client. Subsequent subdirectories in /Pictures however, are not successfully downloaded.
The strange thing is that the directory listing for /Pictures shows subdirectory names that mimic the subdirectory names found at the root of the Android_9 server. (See screenshot of FileZilla client and note the two windows in the Remote Pane)


Accessing the same Android_9 server using plain old Win_10 file explorer and drilling down to /Pictures on the remote server shows the correct subdirectory names. (See screenshot)



Also attached is the contents of the message log pane with verbose mode set.

Code: Select all

Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 0
Status:	Connecting to 192.168.1.93:2121...
Status:	Connection established, waiting for welcome message...
Trace:	CFtpControlSocket::OnReceive()
Response:	220 Service ready for new user.
Trace:	CFtpLogonOpData::ParseResponse() in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 2
Command:	AUTH TLS
Trace:	CFtpControlSocket::OnReceive()
Response:	431 Service is unavailable.
Trace:	CFtpLogonOpData::ParseResponse() in state 2
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 3
Command:	AUTH SSL
Trace:	CFtpControlSocket::OnReceive()
Response:	431 Service is unavailable.
Trace:	CFtpLogonOpData::ParseResponse() in state 3
Status:	Insecure server, it does not support FTP over TLS.
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 5
Trace:	CFtpControlSocket::SetAsyncRequestReply
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 6
Command:	USER janitor
Trace:	CFtpControlSocket::OnReceive()
Response:	331 User name okay, need password for janitor.
Trace:	CFtpLogonOpData::ParseResponse() in state 6
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 6
Command:	PASS ********
Trace:	CFtpControlSocket::OnReceive()
Response:	230 User logged in, proceed.
Trace:	CFtpLogonOpData::ParseResponse() in state 6
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 10
Command:	OPTS UTF8 ON
Trace:	CFtpControlSocket::OnReceive()
Response:	200 Command OPTS okay.
Trace:	CFtpLogonOpData::ParseResponse() in state 10
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpLogonOpData::Send() in state 13
Command:	OPTS MLST size;modify;type;
Trace:	CFtpControlSocket::OnReceive()
Response:	200 Command OPTS okay.
Trace:	CFtpLogonOpData::ParseResponse() in state 13
Status:	Logged in
Trace:	Measured latency of 6 ms
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpLogonOpData::Reset(0) in state 15
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 0
Status:	Retrieving directory listing...
Trace:	CFtpChangeDirOpData::Send() in state 0
Trace:	CFtpChangeDirOpData::Send() in state 1
Command:	PWD
Trace:	CFtpControlSocket::OnReceive()
Response:	257 "/" is current directory.
Trace:	CFtpChangeDirOpData::ParseResponse() in state 1
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpChangeDirOpData::Reset(0) in state 1
Trace:	CFtpListOpData::SubcommandResult(0) in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 2
Trace:	CFtpRawTransferOpData::Send() in state 0
Trace:	CFtpRawTransferOpData::Send() in state 1
Command:	TYPE I
Trace:	CFtpControlSocket::OnReceive()
Response:	200 Command TYPE okay.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 2
Command:	PASV
Trace:	CFtpControlSocket::OnReceive()
Response:	227 Entering Passive Mode (192,168,1,93,167,24)
Trace:	CFtpRawTransferOpData::ParseResponse() in state 2
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 4
Trace:	Binding data connection source IP to control connection source IP 192.168.1.98
Command:	MLSD
Trace:	CTransferSocket::OnConnect
Trace:	CFtpControlSocket::OnReceive()
Response:	150 File status okay; about to open data connection.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 4
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 5
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Alarms
Listing:	Size=4096;Modify=20190308094701.000;Type=dir; Android
Listing:	Size=4096;Modify=20200322150832.000;Type=dir; AnkiDroid
Listing:	Size=4096;Modify=20190307214659.000;Type=dir; Audio
Listing:	Size=4096;Modify=20190307214700.000;Type=dir; Contact
Listing:	Size=4096;Modify=20200501033432.000;Type=dir; DCIM
Listing:	Size=4096;Modify=20190527115747.000;Type=dir; Document
Listing:	Size=4096;Modify=20200509230803.000;Type=dir; Download
Listing:	Size=4096;Modify=20190313184319.000;Type=dir; EBPocket
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Movies
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Music
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Notifications
Listing:	Size=4096;Modify=20190307214700.000;Type=dir; Others
Listing:	Size=4096;Modify=20200411110331.000;Type=dir; PersonalDNSFilter
Listing:	Size=4096;Modify=20200510043716.000;Type=dir; Pictures
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Podcasts
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Ringtones
Listing:	Size=4096;Modify=20200401085810.000;Type=dir; WhatsApp
Listing:	Size=4096;Modify=19700128200250.000;Type=dir; alt_autocycle
Listing:	Size=4096;Modify=20190405071916.000;Type=dir; bluetooth
Listing:	Size=1462;Modify=20190304235654.000;Type=file; wordlist.txt
Trace:	CTransferSocket::TransferEnd(1)
Trace:	CFtpControlSocket::TransferEnd()
Trace:	CFtpControlSocket::OnReceive()
Response:	226 Closing data connection.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 7
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpRawTransferOpData::Reset(0) in state 7
Trace:	CFtpListOpData::SubcommandResult(0) in state 3
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpListOpData::Reset(0) in state 3
Status:	Directory listing of "/" successful
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 0
Status:	Retrieving directory listing of "/Pictures"...
Trace:	CFtpChangeDirOpData::Send() in state 0
Trace:	CFtpChangeDirOpData::Send() in state 2
Command:	CWD /Pictures
Trace:	CFtpControlSocket::OnReceive()
Response:	250 Directory changed to /
Trace:	CFtpChangeDirOpData::ParseResponse() in state 2
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpChangeDirOpData::Reset(0) in state 2
Trace:	CFtpListOpData::SubcommandResult(0) in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 2
Trace:	CFtpRawTransferOpData::Send() in state 0
Trace:	CFtpRawTransferOpData::Send() in state 2
Command:	PASV
Trace:	CFtpControlSocket::OnReceive()
Response:	227 Entering Passive Mode (192,168,1,93,153,169)
Trace:	CFtpRawTransferOpData::ParseResponse() in state 2
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 4
Trace:	Binding data connection source IP to control connection source IP 192.168.1.98
Command:	MLSD
Trace:	CTransferSocket::OnConnect
Trace:	CFtpControlSocket::OnReceive()
Response:	150 File status okay; about to open data connection.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 4
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 5
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Alarms
Listing:	Size=4096;Modify=20190308094701.000;Type=dir; Android
Listing:	Size=4096;Modify=20200322150832.000;Type=dir; AnkiDroid
Listing:	Size=4096;Modify=20190307214659.000;Type=dir; Audio
Listing:	Size=4096;Modify=20190307214700.000;Type=dir; Contact
Listing:	Size=4096;Modify=20200501033432.000;Type=dir; DCIM
Listing:	Size=4096;Modify=20190527115747.000;Type=dir; Document
Listing:	Size=4096;Modify=20200509230803.000;Type=dir; Download
Listing:	Size=4096;Modify=20190313184319.000;Type=dir; EBPocket
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Movies
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Music
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Notifications
Listing:	Size=4096;Modify=20190307214700.000;Type=dir; Others
Listing:	Size=4096;Modify=20200411110331.000;Type=dir; PersonalDNSFilter
Listing:	Size=4096;Modify=20200510043716.000;Type=dir; Pictures
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Podcasts
Listing:	Size=4096;Modify=19700128200217.000;Type=dir; Ringtones
Listing:	Size=4096;Modify=20200401085810.000;Type=dir; WhatsApp
Listing:	Size=4096;Modify=19700128200250.000;Type=dir; alt_autocycle
Listing:	Size=4096;Modify=20190405071916.000;Type=dir; bluetooth
Listing:	Size=1462;Modify=20190304235654.000;Type=file; wordlist.txt
Trace:	CTransferSocket::TransferEnd(1)
Trace:	CFtpControlSocket::TransferEnd()
Trace:	CFtpControlSocket::OnReceive()
Response:	226 Closing data connection.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 7
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpRawTransferOpData::Reset(0) in state 7
Trace:	CFtpListOpData::SubcommandResult(0) in state 3
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpListOpData::Reset(0) in state 3
Status:	Directory listing of "/Pictures" successful
Trace:	CFtpControlSocket::OnReceive()
Status:	Connection closed by server
Trace:	CFtpControlSocket::ResetOperation(66)
Trace:	CControlSocket::ResetOperation(66)

So this directory listing error does not seem to be a problem with the remote FTP server but rather with the FileZilla client. The problematic command would appear to be MLSD

I am a little suspicious of the /Pictures/LINE directory. It happens to be associated with images saved from within LINE messenger which is a popular messenger in Japan. I am speculating that _perhaps_ double-byte ASCII character set (or some other non-UTF8 character set) may be in use. On the surface, this does not _look_ to be the case when viewed from plain old windows file explorer (see screenshot) but maybe someone here can guide me as to how best to debug this further.

[boco]

Command: CWD /Pictures
Trace: CFtpControlSocket::OnReceive()
Response: 250 Directory changed to /

There seems to be a problem on the server, the FTP server does not change the directory to /Pictures when it is requested to do so. This, in turn, confuses FileZilla, as the directory listing again returns the contents of the root (as it was never changed).

[najevi]

Command: CWD /Pictures
Trace: CFtpControlSocket::OnReceive()
Response: 250 Directory changed to /

There seems to be a problem on the server, the FTP server does not change the directory to /Pictures when it is requested to do so. This, in turn, confuses FileZilla, as the directory listing again returns the contents of the root (as it was never changed).

Thank you. After a good night's rest I came to the same conclusion.

I have tried switching from passive mode to active mode and also tried with and without windows defender firewall active but unsurprisingly none of that made a difference.

The perplexing thing is that the content of one subfolder (/Pictures/LINE) was successfully listed at least once and then all those files successfully transferred to the client PC. Only subsequent folders in /Pictures failed to transfer but even those could eventually be transferred using an FTP client other than FileZilla. .. namely windows file explorer. (In an effort to test the CWD command I did try FTP from a windows powershell command line but was unable to make a successful connection to the smart phone's FTP server.)

FileZilla seems like a better solution to run with (than windows file explorer) because I can clearly see logs of queued|failed|successful file transfers. Windows file explorer does not afford this.

So that switches focus to the Android 9 OS and whichever FTP Server is used there. Perhaps the built in Moto File Manager does not handle some specific set of conditions that are necessary for compatibility with FileZilla. Looking for alternative FTP servers, I see that FileZilla Server is only available for Windows, not Android.

• I may experiment with flipping around the client & server roles and try _uploading_ files in bulk _from_ the smart phone client to the PC server.
• Is there a highly recommended FTP Server for Android that is known to work well with FileZilla Client?
  ANSWERING MY OWN QN HERE: I tried WiFi FTP Server and the CWD command executes correctly. Added bonus is FTPS using TLS/SSL is supported. Happy camper!

Does it seem odd to anyone reading this that FileZilla receives a 2xx response following the CWD command when, in reality, that purpose of that command was not achieved?

Does that look to you like a bug in the Motorola FTP server or a bug in the FileZilla client?

[botg]

Does it seem odd to anyone reading this that FileZilla receives a 2xx response following the CWD command when, in reality, that purpose of that command was not achieved?

Not odd, just unfortunate. Seen similar things many times in the past. Mobile FTP implementations being terrible is a known problem. I'm glad you found a working alternative server.