[svlug] Debugging curlftpfs

Akkana Peck akkana at shallowsky.com
Sun Mar 13 10:36:26 PST 2016


Ivan Sergio Borgonovo writes:
> On 03/13/2016 05:00 AM, Akkana Peck wrote:
> 
> > This has been working okay for about a year, but one of the hosting
> > services just switched to a new server, and on the new server, while
> > I can still mount and read files, if I try to upload a file (copy it
> > to the mounted curlftpfs), I get:
> >
> > cp: failed to close '/localmountpoint/filename': Input/output error
> 
> What happens if you just use ftp?

I thought I mentioned that /usr/bin/ftp works fine. So does ncftp.
I don't know what curlftpfs is doing differently.

> Did you try the -v option?

Yes, it didn't print anything useful. -d is a little more helpful,
but mostly what it tells me is that curlftpfs does a lot of
extraneous ftp transfers, it re-logs in twice during the transfer
but seems to reconnect many more times than that (maybe it's
starting some kind of secondary connection?), it looks up the
host in the .netrc file (whatever that is) 7 times for one file
transfer, it does a STOR twice for the same file but there's also
some chatter about truncating it to zero before either of the STORs.

If I try to cp /tmp/asdf /localmountpoint/, here are the only things
that look like they might have useful info:

|    NODEID: 2
|    unique: 3, success, outsize: 144
| unique: 4, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 2087
| open flags: 0x8001 /asdf
|    open[3046116248] flags: 0x8001 /asdf
|    unique: 4, success, outsize: 32
| unique: 5, opcode: GETXATTR (22), nodeid: 2, insize: 68, pid: 2087
|    unique: 5, error: -38 (Function not implemented), outsize: 16
| unique: 6, opcode: SETATTR (4), nodeid: 2, insize: 128, pid: 2087
| truncate /asdf 0

The file /asdf does end up truncated to zero on the server. But
this section of the log happens before either of the two STORs
have happened so I'm not clear if this is relevant.

The first STOR looks like this:

| > PASV
| * Connect data stream passively
| * ftp_perform ends with SECONDARY: 0
| < 227 Entering Passive Mode (172,97,100,110,23,22).
| *   Trying 172.97.100.110...
| * Connecting to 172.97.100.110 (172.97.100.110) port 5910
| * Connected to peecnature.org (172.97.100.110) port 21 (#0)
| > TYPE I
| < 200 Type set to I
| > STOR asdf
| < 150 Opening BINARY mode data connection for asdf
| * Remembering we are in dir ""
| < 226 Transfer complete

The second, quite a bit later, is similar but includes a byte count
(5 is correct, it's just a test file containing the string "asdf").
Still no errors.

Since it's obviously using PASV mode I tried both enable_epsv and
disable_epsv as -o options, but it didn't help. I also tried -o
ftpfs_debug to print more debugging information, but the curlftpfs
man page is lying about that being an option.

| > PASV
| * Connect data stream passively
| * ftp_perform ends with SECONDARY: 0
| < 227 Entering Passive Mode (172,97,100,110,20,10).
| *   Trying 172.97.100.110...
| * Connecting to 172.97.100.110 (172.97.100.110) port 5130
| * Connected to peecnature.org (172.97.100.110) port 21 (#0)
| > TYPE I
| < 200 Type set to I
| > STOR asdf
| < 150 Opening BINARY mode data connection for asdf
|    write[3046116248] 5 bytes to 0
|    unique: 7, success, outsize: 24
| unique: 8, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 2087
| flush[3046116248]
| * Remembering we are in dir ""
| < 226 Transfer complete

Then the errors come at the end, and they don't really tell me
anything beyond the cryptic message I already had from the command
line:

| > PASV
| * Connect data stream passively
| * ftp_perform ends with SECONDARY: 0
| < 227 Entering Passive Mode (172,97,100,110,22,161).
| *   Trying 172.97.100.110...
| * Connecting to 172.97.100.110 (172.97.100.110) port 5793
| * Connected to peecnature.org (172.97.100.110) port 21 (#0)
| > LIST -a
| < 150 Opening ASCII mode data connection for file list
| * Maxdownload = -1
| * Remembering we are in dir ""
| < 226 Transfer complete
| * Connection #0 to host peecnature.org left intact
| ftpfs_flush: check filesize problem: size=0 expected=5
| ftpfs: operation ftpfs_flush failed because Input/output error
|    unique: 8, error: -5 (Input/output error), outsize: 16
| unique: 9, opcode: RELEASE (18), nodeid: 2, insize: 64, pid: 0
| release[3046116248] flags: 0x8001
|    unique: 9, success, outsize: 16
| unique: 10, opcode: BATCH_FORGET (42), nodeid: 0, insize: 80, pid: 0
| FORGET 2/1
| DELETE: 2
| FORGET 1/1

Full log on request (need to sanitize it, it includes the password
as it reconnects for no apparent reason).

Googling ftpfs_flush failed did get a lot more hits than the
original error message, though, including one with a patch in
github, so I'll try building my own local version of curlftpfs and
see if that helps. I still haven't found anyone who seems to have a
clue why it happens on some servers and not others.

        ...Akkana



More information about the svlug mailing list