How do I resolve directory listing errors in WinSCP FTP connected to mTCP running on a FreeDOS VM?

Question

I'm running a FreeDos v1.1 VirtualBox guest on a Windows 7 64-bit host. Today I ran mTCP's ftpsrv.exe for FTP access and FTP'd into FreeDos using WinSCP. It started me in my last accessed directory, which was /DRIVE_C/RR2. I browsed to the root directory (/DRIVE_C) and uploaded a small file. After the file transfer completed, WinSCP hanged on the file transfer before telling me the connection was broken and that it failed to retrieve the directory listing:

Timeout detected. (data connection)
Could not retrieve directory listing
Error listing directory '/DRIVE_C'.

Initially I thought there had been a disk error, but the file was successfully uploaded and everything else seemed to be in order.

Trying to reconnect, however, results in the same error. Clearing the remote directory setting from WinSCP solves nothing. I created a new user and logging in that way still received the same error.

What I can do is manually specify the starting directory to almost any subdirectory other than /DRIVE_C or /DRIVE_C/FDOS. Directories are randomly "not found," causing WinSCP to disconnect, and WinSCP will randomly choke and disconnect while transferring files. Sometimes I can copy a file in FreeDOS to a different location then download it via FTP, but sometimes not. Uploading a file will usually render its directory invisible to FTP.

The VM has a 2GB disk and is half empty, so the disk isn't low on space.

After wasting hours trying to troubleshoot this, I finally said "screw it" and installed a FreeDOS 1.2 VM guest. I downloaded as many games files as I could from my FreeDos 1.1 VM, then started uploading them to my new FreeDOS 1.2 VM. I decided to put the game files under /DRIVE_C/GAMES/ and drag-n-dropped them from my host to the guest via WinSCP. WinSCP timed out and resumed a few times before choking on a directory listing error and then quitting with an "abnormal execution" error. I can no longer access /DRIVE_C/GAMES/ via FTP (but have no problem when working directly on the system).

Here's my ftpsrv user setup on both FreeDOS VMs:

# userid password sandbox_directory incoming_directory permissions
redacted redacted [none]            [any]              all

According to this, my login should have full access with no restrictions.

mTCP configuration on FreeDOS 1.1 (mostly default settings)

packetint 0x60
mtu 1472
DOSRules
ftpsrv_password_file c:\FDOS\ftppass.txt
ftpsrv_log_file c:\FDOS\ftpsrv.log
ftpsrv_filebuffer_size 16
ftpsrv_tcpbuffer_size 16
ftpsrv_packets_per_roll 2

mTCP configuration on FreeDOS 1.2 (mostly default settings)

packetint 0x60
mtu 1500
DOSRules
ftpsrv_password_file c:\FDOS\ftppass.txt
ftpsrv_log_file c:\FDOS\ftpsrv.log
# I forgot to uncomment these, but seems to have made no difference
#ftpsrv_filebuffer_size 16
#ftpsrv_tcpbuffer_size 16
#ftpsrv_packets_per_roll 2

I somehow doubt WinSCP is the culprit here, even though interacting with mTCP seems to be making it wonky. I use WinSCP nearly every day to connect to other systems, and I've never encountered this kind of behavior.

WinSCP configuration for both connections:

Protocol: FTP
Encryption: No encryption
Port number: 21
UTF-8 encoding for filenames: Auto
[ ] Trim VMS version numbers
[ ] Synchronize browsing
[x] Remember last used directory (turning this off didn't help)
[x] Cache visited remote directories
[x] Cache directory changes
[x] Permanent cache
[x] Resolve symbolic links
[ ] Follow symbolic links to directories
[ ] Preserve deleted files to recycle bin
[x] Passive mode
Protocal options: All auto
Server response timeout: 15
Keepalives: Executing dummy protocol commands
Seconds between keepalives: 30
Internet protocol version: Auto
Proxy type: None

I'm inclined to believe the fault lies in an OS permission setting. I can however find no documentation about file permissions in FreeDos. The closest I can find is attributes, which gives me the following information (on FreeDOS 1.1):

[D----] FDOS
[----A] KERNAL.SYS
[----A] AUTOEXEC.BAT
[----A] COMMAND.COM
[----A] FDCONFIG.SYS
[----A] BOOTSECT.BIN
[D----] DUKE3D
[D----] RR2

which clearly have nothing to do with permissions.

Update 2017.04.03: As requested, here are my log files. (WinSCP wasn't logging, so this is from this morning.)

Log file from WinSCP:

. 2017-04-03 10:22:22.641 --------------------------------------------------------------------------
. 2017-04-03 10:22:22.642 WinSCP Version 5.9.4 (Build 7333) (OS 6.1.7601 Service Pack 1 - Windows 7 Professional)
. 2017-04-03 10:22:22.643 Configuration: C:\Users\Redacted\AppData\Roaming\winscp.ini
. 2017-04-03 10:22:22.643 Log level: Normal
. 2017-04-03 10:22:22.643 Local account: Redacted
. 2017-04-03 10:22:22.644 Working directory: C:\Users\Redacted
. 2017-04-03 10:22:22.644 Process ID: 7508
. 2017-04-03 10:22:22.644 Command-line: "C:\Windows\winscp.exe" 
. 2017-04-03 10:22:22.644 Time zone: Current: GMT-6, Standard: GMT-7 (Mountain Standard Time), DST: GMT-6 (Mountain Daylight Time), DST Start: 3/12/2017, DST End: 11/5/2017
. 2017-04-03 10:22:22.644 Login time: Monday, April 03, 2017 10:22:22 AM
. 2017-04-03 10:22:22.644 --------------------------------------------------------------------------
. 2017-04-03 10:22:22.644 Session name: FreeDos 1.1 (Modified site)
. 2017-04-03 10:22:22.644 Host name: 192.168.1.123 (Port: 21)
. 2017-04-03 10:22:22.644 User name: redacted (Password: No, Key file: No, Passphrase: No)
. 2017-04-03 10:22:22.644 Transfer Protocol: FTP
. 2017-04-03 10:22:22.644 Ping type: Dummy, Ping interval: 30 sec; Timeout: 5 sec
. 2017-04-03 10:22:22.644 Disable Nagle: No
. 2017-04-03 10:22:22.644 Proxy: None
. 2017-04-03 10:22:22.644 Send buffer: 262144
. 2017-04-03 10:22:22.644 UTF: Auto
. 2017-04-03 10:22:22.644 FTPS: None [Client certificate: No]
. 2017-04-03 10:22:22.645 FTP: Passive: Yes [Force IP: Auto]; MLSD: Auto [List all: Auto]; HOST: Auto
. 2017-04-03 10:22:22.645 Local directory: C:\TEMP\FdDOS, Remote directory: /DRIVE_C/UP, Update: Yes, Cache: Yes
. 2017-04-03 10:22:22.645 Cache directory changes: Yes, Permanent: Yes
. 2017-04-03 10:22:22.645 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2017-04-03 10:22:22.645 Timezone offset: 0h 0m
. 2017-04-03 10:22:22.645 --------------------------------------------------------------------------
. 2017-04-03 10:22:22.774 Connecting to 192.168.1.123 ...
. 2017-04-03 10:22:22.774 Connected with 192.168.1.123. Waiting for welcome message...
< 2017-04-03 10:22:22.774 220 mTCP FTP Server
> 2017-04-03 10:22:22.774 USER redacted
< 2017-04-03 10:22:22.775 331 User OK, send Password
> 2017-04-03 10:22:26.075 PASS ********
< 2017-04-03 10:22:26.281 230 User logged in
> 2017-04-03 10:22:26.281 SYST
< 2017-04-03 10:22:26.281 215 UNIX Type: L8
> 2017-04-03 10:22:26.281 FEAT
< 2017-04-03 10:22:26.282 211-mTCP FTP server features:
< 2017-04-03 10:22:26.282  MDTM
< 2017-04-03 10:22:26.282 211 End
. 2017-04-03 10:22:26.327 Connected
. 2017-04-03 10:22:26.327 --------------------------------------------------------------------------
. 2017-04-03 10:22:26.327 Using FTP protocol.
. 2017-04-03 10:22:26.329 Doing startup conversation with host.
> 2017-04-03 10:22:26.379 PWD
< 2017-04-03 10:22:26.380 257 "/" is current directory
. 2017-04-03 10:22:26.380 Changing directory to "/DRIVE_C/UP".
> 2017-04-03 10:22:26.380 CWD /DRIVE_C/UP
< 2017-04-03 10:22:26.381 250 CWD command successful
. 2017-04-03 10:22:26.381 Getting current directory name.
> 2017-04-03 10:22:26.381 PWD
< 2017-04-03 10:22:26.381 257 "/DRIVE_C/UP/" is current directory
. 2017-04-03 10:22:26.581 Retrieving directory listing...
> 2017-04-03 10:22:26.581 TYPE A
< 2017-04-03 10:22:26.581 200 Type set to A
> 2017-04-03 10:22:26.582 PASV
< 2017-04-03 10:22:26.582 227 Entering Passive Mode (192,168,1,123,8,42)
> 2017-04-03 10:22:26.582 LIST -a
. 2017-04-03 10:22:26.582 Connecting to 192.168.1.123:2090 ...
< 2017-04-03 10:22:26.583 150 Sending file list
. 2017-04-03 10:22:26.583 Data connection closed
. 2017-04-03 10:22:26.583 <Empty directory listing>
< 2017-04-03 10:22:26.584 226 Transfer complete
. 2017-04-03 10:22:26.584 Directory listing successful
. 2017-04-03 10:22:26.584 LIST with -a switch returned empty directory listing, will try pure LIST
. 2017-04-03 10:22:26.584 Retrieving directory listing...
> 2017-04-03 10:22:26.584 TYPE A
< 2017-04-03 10:22:26.584 200 Type set to A
> 2017-04-03 10:22:26.585 PASV
< 2017-04-03 10:22:26.585 227 Entering Passive Mode (192,168,1,123,8,91)
> 2017-04-03 10:22:26.585 LIST
. 2017-04-03 10:22:26.585 Connecting to 192.168.1.123:2139 ...
< 2017-04-03 10:22:26.586 150 Sending file list
. 2017-04-03 10:22:26.586 Data connection closed
. 2017-04-03 10:22:26.586 <Empty directory listing>
< 2017-04-03 10:22:26.586 226 Transfer complete
. 2017-04-03 10:22:26.586 Directory listing successful
. 2017-04-03 10:22:26.587 ..;D;0;1899-12-30T07:00:00.000Z;0;"" [0];"" [0];---------;0
. 2017-04-03 10:22:26.681 Startup conversation with host finished.
. 2017-04-03 10:22:30.251 Cached directory change via ".." to "/DRIVE_C".
. 2017-04-03 10:22:30.251 Getting current directory name.
. 2017-04-03 10:22:30.254 Retrieving directory listing...
> 2017-04-03 10:22:30.254 CWD /DRIVE_C/
< 2017-04-03 10:22:30.254 250 CWD command successful
> 2017-04-03 10:22:30.254 PWD
< 2017-04-03 10:22:30.254 257 "/DRIVE_C/" is current directory
> 2017-04-03 10:22:30.254 TYPE A
< 2017-04-03 10:22:30.254 200 Type set to A
> 2017-04-03 10:22:30.254 PASV
< 2017-04-03 10:22:30.254 227 Entering Passive Mode (192,168,1,123,11,61)
> 2017-04-03 10:22:30.254 LIST
. 2017-04-03 10:22:30.254 Connecting to 192.168.1.123:2877 ...
< 2017-04-03 10:22:30.256 150 Sending file list
. 2017-04-03 10:22:30.256 Data connection closed
< 2017-04-03 10:22:30.256 226 Transfer complete
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Jul 14  2016 FDOS
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp      45344 Jun 21  2011 KERNEL.SYS
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp       1266 Apr  2 06:26 AUTOEXEC.BAT
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp      66945 Aug 28  2006 COMMAND.COM
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp        848 Jul 14  2016 FDCONFIG.SYS
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp        512 Jul 14  2016 BOOTSECT.BIN
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Jul 14  2016 RR
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Jul 14  2016 ATOMIC
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Jul 14  2016 DUKE3D
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Jul 30  2016 RR2
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Aug  9  2016 HUNT
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Apr  2 08:13 TEST
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp        527 Apr  2 07:09 README.TXT
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Apr  2 18:23 DCINST
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Apr  2 18:26 DUKEDC
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Apr  2 18:36 ERR200
. 2017-04-03 10:22:30.256 drwxrwxrwx 1 ftp ftp          0 Apr  2 18:39 UP
. 2017-04-03 10:22:30.256 -rwxrwxrwx 1 ftp ftp        161 Apr  2 18:44 GAMER.INI
. 2017-04-03 10:22:30.266 Directory listing successful
. 2017-04-03 10:22:30.266 ..;D;0;1899-12-30T07:00:00.000Z;0;"" [0];"" [0];---------;0
. 2017-04-03 10:22:30.266 FDOS;D;0;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.266 KERNEL.SYS;-;45344;2011-06-21T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.266 AUTOEXEC.BAT;-;1266;2017-04-02T12:26:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.266 COMMAND.COM;-;66945;2006-08-28T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.266 FDCONFIG.SYS;-;848;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.266 BOOTSECT.BIN;-;512;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 RR;D;0;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 ATOMIC;D;0;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 DUKE3D;D;0;2016-07-14T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 RR2;D;0;2016-07-30T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 HUNT;D;0;2016-08-09T06:00:00.000Z;2;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 TEST;D;0;2017-04-02T14:13:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 README.TXT;-;527;2017-04-02T13:09:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 DCINST;D;0;2017-04-03T00:23:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 DUKEDC;D;0;2017-04-03T00:26:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 ERR200;D;0;2017-04-03T00:36:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 UP;D;0;2017-04-03T00:39:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:30.267 GAMER.INI;-;161;2017-04-03T00:44:00.000Z;1;"ftp" [0];"ftp" [0];rwxrwxrwx;1
. 2017-04-03 10:22:34.312 Cached directory change via "FDOS" to "/DRIVE_C/FDOS".
. 2017-04-03 10:22:34.312 Getting current directory name.
. 2017-04-03 10:22:34.316 Retrieving directory listing...
> 2017-04-03 10:22:34.316 CWD /DRIVE_C/FDOS/
< 2017-04-03 10:22:34.317 250 CWD command successful
> 2017-04-03 10:22:34.317 PWD
< 2017-04-03 10:22:34.317 257 "/DRIVE_C/FDOS/" is current directory
> 2017-04-03 10:22:34.317 TYPE A
< 2017-04-03 10:22:34.317 200 Type set to A
> 2017-04-03 10:22:34.317 PASV
< 2017-04-03 10:22:34.317 227 Entering Passive Mode (192,168,1,123,9,182)
> 2017-04-03 10:22:34.317 LIST
. 2017-04-03 10:22:34.317 Connecting to 192.168.1.123:2486 ...
< 2017-04-03 10:22:34.317 150 Sending file list
< 2017-04-03 10:22:34.317 226 Transfer complete
. 2017-04-03 10:22:39.872 Timeout detected. (data connection)
. 2017-04-03 10:22:39.872 Could not retrieve directory listing
. 2017-04-03 10:22:39.872 Connection was lost, asking what to do.
. 2017-04-03 10:22:39.872 Asking user:
. 2017-04-03 10:22:39.872 Lost connection. ("Timeout detected. (data connection)","Could not retrieve directory listing")
* 2017-04-03 10:22:41.881 (ESshFatal) **Lost connection.**
* 2017-04-03 10:22:41.881 Timeout detected. (data connection)
* 2017-04-03 10:22:41.881 Could not retrieve directory listing
* 2017-04-03 10:22:41.881 Error listing directory '/DRIVE_C/FDOS'.
* 2017-04-03 10:22:41.881 Error changing directory to 'FDOS'.

Log file from mTCP on FreeDOS 1.1

2017-04-03 10:17:37.40 mTCP FtpSrv version (Oct 29 2011) starting

2017-04-03 10:17:37.40 Clients: 3, Client file buffer size: 16384, TCP buffer size: 16384
2017-04-03 10:17:37.40 Packets per poll: 2, TCP sockets: 10, Send buffers: 15, Recv buffers: 40
2017-04-03 10:17:37.40 Client session timeout: 182 seconds
2017-04-03 10:17:37.40 Control port: 21, Pasv ports: 2048-3071
2017-04-03 10:17:37.46 Real IP address: 192.168.1.123, Pasv response IP addr: 192.168.1.123
2017-04-03 10:17:49.65 (0) User redacted signed in from 192.168.1.147:51304 at 2017-04-03 10:17:44
2017-04-03 10:18:09.31 (0) Disconnect: 192.168.1.147:51304
2017-04-03 10:22:23.84 (1) User redacted signed in from 192.168.1.147:51316 at 2017-04-03 10:22:20
2017-04-03 10:22:37.62 (1) Disconnect: 192.168.1.147:51316
2017-04-03 10:36:36.83 (2) User redacted signed in from 192.168.1.147:51365 at 2017-04-03 10:36:33
2017-04-03 10:36:51.39 (2) Disconnect: 192.168.1.147:51365
2017-04-03 10:36:55.83 Shutdown requested
2017-04-03 10:36:56.88 Stats: Sessions: 3  Timeouts: 0
2017-04-03 10:36:56.88        LIST: 11  NLST: 0  RETR: 0
2017-04-03 10:36:56.88        STOR: 0  STOU: 0  APPE: 0
2017-04-03 10:36:56.88 === Server shutdown === 

Update: I tried with Core FTP, and here's its log:

Welcome to Core FTP, release ver 2.2, build 1887 (x64) -- © 2003-2016
WinSock 2.0
Mem -- 33,531,236 KB, Virt -- 8,589,934,464 KB
Started on Monday April 03, 2017 at 11:36:AM
Connect socket #752 to 192.168.1.123, port 21...220 mTCP FTP Server

USER redacted
331 User OK, send Password
PASS **********
230 User logged in
SYST
215 UNIX Type: L8
Keep alive off...PWD
257 "/" is current directory
PASV
227 Entering Passive Mode (192,168,1,123,10,76)
LIST
Connect socket #800 to 192.168.1.123, port 2636...150 Sending file list
226 Transfer complete
Transferred 54 bytes in 60.000 seconds
CWD /DRIVE_C
250 CWD command successful
PASV
227 Entering Passive Mode (192,168,1,123,9,147)
LIST
Connect socket #844 to 192.168.1.123, port 2451...150 Sending file list
226 Transfer complete
Transferred 1,028 bytes in 60.001 seconds
CWD /DRIVE_C/FDOS/
250 CWD command successful
PASV
227 Entering Passive Mode (192,168,1,123,8,41)
LIST
Connect socket #960 to 192.168.1.123, port 2089...150 Sending file list
226 Transfer complete
Transferred 1,279 bytes in 0.001 seconds
CDUP
250 CWD command successful
PWD
257 "/DRIVE_C/" is current directory
PASV
227 Entering Passive Mode (192,168,1,123,8,67)
LIST
Connect socket #972 to 192.168.1.123, port 2115...150 Sending file list
226 Transfer complete
Transferred 1,028 bytes in 60.001 seconds
QUIT
221 Server closing connection
Total uploaded files:  0
Total uploaded data:  0
Total downloaded files:  0
Total downloaded data:  0

As you can see, it took just over 60 seconds to retrieve 54 bytes of directory information. Core FTP seems to be more successful, in that it eventually gets the directory listing. Some times it works quickly like you would expect FTP to, like when it transferred 1,279 bytes in 0.001 seconds, but it still seems to be hit and miss.

I thought maybe I just wasn't letting WinSCP wait long enough, so I increased the timeout to two minutes. The only different behavior was that WinSCP hanged for two full minutes before displaying the error.

The mTCP log from these latest two attempts shows nothing more than "User signed in" and "Disconnect" with 0 timeouts and no errors, just like the full log further up this page.

I started thinking the router might be the issue, so I turned off and back on, but that made no difference. My computer is wired directly to the router by a 3-foot cord, and all other internet usage seems normal, so I'm not likely experiencing network interference.

Maybe its time I file a bug with the developer of mTCP and see what he comes up with.