Announcement

Collapse
No announcement yet.

14128 File delete failure on Fastmail FTP

Collapse
X
  • Filter
  • Time
  • Show
Clear All
new posts

  • 14128 File delete failure on Fastmail FTP

    On the Fastmail FM FTP server, BC "Simultaneous connections: 2" gives file delete failures - log below and profile in email to Support. No such failures from Filezilla - log below.

    Workaround: set "Simultaneous connections: 1".

    BC
    Code:
    2012-01-11 22:00:12  Username: OWNER-ZBB5FTV33\Chris
    2012-01-11 22:00:13  Stat> Connected.
    2012-01-11 22:00:13  Recv> 220 frontend1 FTP server (Net::FTPServer/1.122-1 ME::VFS::Interface::FTP/22691) ready.
    2012-01-11 22:00:13  Sent> HOST ftp.messagingengine.com
    2012-01-11 22:00:13  Recv> 200 HOST set to ftp.messagingengine.com.
    2012-01-11 22:00:13  Sent> USER chrisjj@fastmail.fm
    2012-01-11 22:00:13  Recv> 331 Username OK, please send password.
    2012-01-11 22:00:13  Sent> PASS ********
    2012-01-11 22:00:14  Recv> 230 Welcome chrisjj@fastmail.fm.
    2012-01-11 22:00:14  Sent> FEAT
    2012-01-11 22:00:14  Recv> 211-Extensions supported:
    2012-01-11 22:00:14  Recv>  AUTH TLS
    2012-01-11 22:00:14         CCC
    2012-01-11 22:00:14         HASH SHA-1*
    2012-01-11 22:00:14         HOST
    2012-01-11 22:00:14         LANG EN*
    2012-01-11 22:00:14         MDTM
    2012-01-11 22:00:14         MFMT
    2012-01-11 22:00:14         MLST TYPE*;SIZE*;MODIFY*;PERM*;UNIX.MODE*;
    2012-01-11 22:00:14         PBSZ
    2012-01-11 22:00:14         PROT
    2012-01-11 22:00:14         REST STREAM
    2012-01-11 22:00:14         SIZE
    2012-01-11 22:00:14         TVFS
    2012-01-11 22:00:14         UTF8
    2012-01-11 22:00:14         UTIME
    2012-01-11 22:00:14        211 END
    2012-01-11 22:00:14  Sent> TYPE I
    2012-01-11 22:00:14  Recv> 200 TYPE changed to I.
    2012-01-11 22:00:14  Sent> SYST
    2012-01-11 22:00:14  Recv> 215 UNIX Type: L8
    2012-01-11 22:00:14  Sent> OPTS UTF8 ON
    2012-01-11 22:00:14  Recv> 501 Command has no settable options.
    2012-01-11 22:00:14  Sent> PWD
    2012-01-11 22:00:14  Recv> 257 "/"
    2012-01-11 22:00:14  Sent> REST 1
    2012-01-11 22:00:14  Recv> 350 Restarting next transfer at 1.
    2012-01-11 22:00:14  Sent> REST 0
    2012-01-11 22:00:15  Recv> 350 Restarting next transfer at 0.
    2012-01-11 22:00:15  Sent> CWD chrisjj.fastmail.fm/files/chrisjj.com/tango/clips
    2012-01-11 22:00:15  Recv> 250 Changed directory OK.
    2012-01-11 22:00:15  Sent> PWD
    2012-01-11 22:00:15  Recv> 257 "/chrisjj.fastmail.fm/files/chrisjj.com/tango/clips"
    2012-01-11 22:00:15  Sent> PASV
    2012-01-11 22:00:15  Recv> 227 Entering Passive Mode (66,111,4,57,202,183)
    2012-01-11 22:00:15  Sent> MLSD
    2012-01-11 22:00:15  Recv> 150 Opening data connection for file listing.
    2012-01-11 22:00:17  Recv> 226 Listing complete. Data connection has been closed.
    2012-01-11 22:00:17  Load comparison: D:\Projects\ChrisJJ\chrisjj.com web\www.chrisjj.com\tango\clips <-> ftp://chrisjj@fastmail.fm@ftp.messagingengine.com/chrisjj.fastmail.fm/files/chrisjj.com/tango/clips
    2012-01-11 22:00:21  Sent> DELE 02480002928225-1-100.mp3
    2012-01-11 22:00:22  Stat> Connected.
    2012-01-11 22:00:22  Recv> 250 File has been deleted.
    2012-01-11 22:00:22  Sent> DELE 02480002928225-1-102.mp3
    2012-01-11 22:00:22  Recv> 220 frontend1 FTP server (Net::FTPServer/1.122-1 ME::VFS::Interface::FTP/22691) ready.
    2012-01-11 22:00:22  Sent> USER chrisjj@fastmail.fm
    2012-01-11 22:00:22  Recv> 331 Username OK, please send password.
    2012-01-11 22:00:22  Sent> PASS ********
    2012-01-11 22:00:22  Recv> 250 File has been deleted.
    2012-01-11 22:00:22  Sent> DELE 02480002928225-1-103.mp3
    2012-01-11 22:00:22  Recv> 230 Welcome chrisjj@fastmail.fm.
    2012-01-11 22:00:22  Sent> FEAT
    2012-01-11 22:00:22  Recv> 211-Extensions supported:
    2012-01-11 22:00:23  Recv>  AUTH TLS
    2012-01-11 22:00:23         CCC
    2012-01-11 22:00:23         HASH SHA-1*
    2012-01-11 22:00:23         HOST
    2012-01-11 22:00:23         LANG EN*
    2012-01-11 22:00:23         MDTM
    2012-01-11 22:00:23         MFMT
    2012-01-11 22:00:23         MLST TYPE*;SIZE*;MODIFY*;PERM*;UNIX.MODE*;
    2012-01-11 22:00:23         PBSZ
    2012-01-11 22:00:23         PROT
    2012-01-11 22:00:23         REST STREAM
    2012-01-11 22:00:23         SIZE
    2012-01-11 22:00:23         TVFS
    2012-01-11 22:00:23         UTF8
    2012-01-11 22:00:23         UTIME
    2012-01-11 22:00:23        211 END
    2012-01-11 22:00:23  Sent> TYPE I
    2012-01-11 22:00:23  Recv> 250 File has been deleted.
    2012-01-11 22:00:23  Sent> DELE 02480002928225-1-104.mp3
    2012-01-11 22:00:23  Recv> 200 TYPE changed to I.
    2012-01-11 22:00:23  Sent> SYST
    2012-01-11 22:00:23  Recv> 215 UNIX Type: L8
    2012-01-11 22:00:23  Sent> OPTS UTF8 ON
    2012-01-11 22:00:23  Recv> 501 Command has no settable options.
    2012-01-11 22:00:23  Sent> PWD
    2012-01-11 22:00:23  Recv> 257 "/"
    2012-01-11 22:00:23  Sent> REST 1
    2012-01-11 22:00:23  Recv> 350 Restarting next transfer at 1.
    2012-01-11 22:00:23  Sent> REST 0
    2012-01-11 22:00:23  Recv> 350 Restarting next transfer at 0.
    2012-01-11 22:00:23  Sent> CWD /chrisjj.fastmail.fm/files/chrisjj.com/tango/clips
    2012-01-11 22:00:23  Recv> 250 File has been deleted.
    2012-01-11 22:00:23  Sent> DELE 02480002928225-1-105.mp3
    2012-01-11 22:00:23  Recv> 250 Changed directory OK.
    2012-01-11 22:00:23  Sent> DELE 02480002928225-1-101.mp3
    2012-01-11 22:00:24  Recv> 250 File has been deleted.
    2012-01-11 22:00:24  Sent> DELE 02480002928225-1-106.mp3
    2012-01-11 22:00:24  Recv> 250 File has been deleted.
    2012-01-11 22:00:24  Sent> DELE 02480002928225-1-107.mp3
    2012-01-11 22:00:25  Recv> 250 File has been deleted.
    2012-01-11 22:00:25  Sent> DELE 02480002928225-1-108.mp3
    2012-01-11 22:00:25  Stat> Disconnected.
    2012-01-11 22:00:26  Stat> Connected.
    2012-01-11 22:00:26  Recv> 220 frontend1 FTP server (Net::FTPServer/1.122-1 ME::VFS::Interface::FTP/22691) ready.
    2012-01-11 22:00:26  Sent> USER chrisjj@fastmail.fm
    2012-01-11 22:00:26  Recv> 331 Username OK, please send password.
    2012-01-11 22:00:26  Sent> PASS ********
    2012-01-11 22:00:26  Recv> 250 File has been deleted.
    2012-01-11 22:00:26  Sent> DELE 02480002928225-1-109.mp3
    2012-01-11 22:00:26  Recv> 230 Welcome chrisjj@fastmail.fm.
    2012-01-11 22:00:26  Sent> FEAT
    2012-01-11 22:00:26  Recv> 211-Extensions supported:
    2012-01-11 22:00:27  Recv>  AUTH TLS
    2012-01-11 22:00:27         CCC
    2012-01-11 22:00:27         HASH SHA-1*
    2012-01-11 22:00:27         HOST
    2012-01-11 22:00:27         LANG EN*
    2012-01-11 22:00:27         MDTM
    2012-01-11 22:00:27         MFMT
    2012-01-11 22:00:27         MLST TYPE*;SIZE*;MODIFY*;PERM*;UNIX.MODE*;
    2012-01-11 22:00:27         PBSZ
    2012-01-11 22:00:27         PROT
    2012-01-11 22:00:27         REST STREAM
    2012-01-11 22:00:27         SIZE
    2012-01-11 22:00:27         TVFS
    2012-01-11 22:00:27         UTF8
    2012-01-11 22:00:27         UTIME
    2012-01-11 22:00:27        211 END
    2012-01-11 22:00:27  Sent> TYPE I
    2012-01-11 22:00:27  Recv> 200 TYPE changed to I.
    2012-01-11 22:00:27  Sent> SYST
    2012-01-11 22:00:27  Recv> 250 File has been deleted.
    2012-01-11 22:00:27  Sent> DELE 02480002928225-1-110.mp3
    2012-01-11 22:00:27  Recv> 215 UNIX Type: L8
    2012-01-11 22:00:27  Sent> OPTS UTF8 ON
    2012-01-11 22:00:27  Recv> 501 Command has no settable options.
    2012-01-11 22:00:27  Sent> PWD
    2012-01-11 22:00:27  Recv> 257 "/"
    2012-01-11 22:00:27  Sent> CWD /chrisjj.fastmail.fm/files/chrisjj.com/tango/clips
    2012-01-11 22:00:27  Recv> 250 Changed directory OK.
    2012-01-11 22:00:27  Sent> DELE 02480002928225-1-107.mp3
    2012-01-11 22:00:27  Recv> 250 File has been deleted.
    2012-01-11 22:00:27  Sent> DELE 02480002928225-1-111.mp3
    2012-01-11 22:00:28  Recv> 250 File has been deleted.
    2012-01-11 22:00:28  Sent> DELE 02480002928225-1-112.mp3
    2012-01-11 22:00:28  Stat> Disconnected.
    2012-01-11 22:00:28  Unable to delete ftp://chrisjj@fastmail.fm@ftp.messagingengine.com/chrisjj.fastmail.fm/files/chrisjj.com/tango/clips/02480002928225-1-107.mp3: Connection Closed Gracefully.
    2012-01-11 22:00:28  Stat> Connected.
    2012-01-11 22:00:28  Recv> 220 frontend1 FTP server (Net::FTPServer/1.122-1 ME::VFS::Interface::FTP/22691) ready.
    2012-01-11 22:00:28  Sent> USER chrisjj@fastmail.fm
    2012-01-11 22:00:29  Recv> 331 Username OK, please send password.
    [etc.]
    Filezilla
    Code:
    Status:	Resolving address of ftp.messagingengine.com
    Status:	Connecting to 66.111.4.57:21...
    Status:	Connection established, waiting for welcome message...
    Response:	220 frontend1 FTP server (Net::FTPServer/1.122-1 ME::VFS::Interface::FTP/22691) ready.
    Command:	USER chrisjj@fastmail.fm
    Response:	331 Username OK, please send password.
    Command:	PASS *******
    Response:	230 Welcome chrisjj@fastmail.fm.
    Command:	SYST
    Response:	215 UNIX Type: L8
    Command:	FEAT
    Response:	211-Extensions supported:
    Response:	 AUTH TLS
    Response:	 CCC
    Response:	 HASH SHA-1*
    Response:	 HOST
    Response:	 LANG EN*
    Response:	 MDTM
    Response:	 MFMT
    Response:	 MLST TYPE*;SIZE*;MODIFY*;PERM*;UNIX.MODE*;
    Response:	 PBSZ
    Response:	 PROT
    Response:	 REST STREAM
    Response:	 SIZE
    Response:	 TVFS
    Response:	 UTF8
    Response:	 UTIME
    Response:	211 END
    Command:	OPTS UTF8 ON
    Response:	501 Command has no settable options.
    Status:	Connected
    Status:	Retrieving directory listing...
    Command:	CWD /chrisjj.fastmail.fm/files/chrisjj.com/tango/clips
    Response:	250 Changed directory OK.
    Command:	PWD
    Response:	257 "/chrisjj.fastmail.fm/files/chrisjj.com/tango/clips"
    Command:	TYPE I
    Response:	200 TYPE changed to I.
    Command:	PASV
    Response:	227 Entering Passive Mode (66,111,4,57,207,226)
    Command:	MLSD
    Response:	150 Opening data connection for file listing.
    Response:	226 Listing complete. Data connection has been closed.
    Status:	Directory listing successful
    Command:	DELE 00743216334629-1-11.mp3
    Response:	250 File has been deleted.
    Command:	DELE 00743216334629-1-14.mp3
    Response:	250 File has been deleted.
    Command:	DELE 02480002928225-1-107.mp3
    Response:	250 File has been deleted.
    Command:	DELE 02480002928225-1-118.mp3
    Response:	250 File has been deleted.
    Command:	DELE 02480002928225-1-124.mp3
    [etc.]

  • #2
    It appears to be an issue with FastMail's FTP server. It disconnects when you use multiple connections for any commands, but BC handles disconnects during uploads/downloads more gracefully than deletes. FileZilla appears to have the same disconnects happen, but it only uses a single connection for deletes, even if you have multiple connections configured, which is why you aren't seeing it.

    I ran into some sort of bandwidth quota when I was testing this with my account, so I can't do more right now. I've opened a support ticket with FastMail and I'll look into it further once they get back to me.
    ZoŽ P Scooter Software

    Comment


    • #3
      Thanks Craig.


      EDIT: FTR, I find my comparison above unsafe and my workaround unreliable. I get variable results consistent with Craig's quota theory, even on a fresh Fastmail account.
      Last edited by chrisjj; 19-Jan-2012, 05:53 PM.

      Comment


      • #4
        By you workaround being unreliable, you're referring to setting the number of connections to 1?

        I've heard back from their FTP developer, and I did some more testing myself once the quota reset. I have confirmed that BC itself is working correctly. If BC tries to do a file operation and the server has disconnected we reconnect and try it again. That's designed to automatically handle idle timeouts and the like. In FastMail's case, the server is unstable enough that it disconnects again the second time we try sending the command. At that point we've tried it twice and disconnected both times, so BC gives up and moves on to the next request. Uploads have the same problem, but the resume support means we retry a bit more aggressively.

        They have reproduced the errors I saw and are looking into it, and they've said they're working on a new implementation that should help. For now I can only recommend sticking with a single connection and being conservative in what you use it for. If you need something more resilient consider a dedicated FTP hosting provider.
        ZoŽ P Scooter Software

        Comment


        • #5
          > By you workaround being unreliable, you're
          > referring to setting the number of connections to 1?

          Yes. It worked initially, but failed subsequently.

          > I've heard back from their FTP developer, and I did some more testing
          > myself once the quota reset. I have confirmed that BC itself is working
          > correctly.

          My impression too now.. having found that the success on FileZilla was ephemeral.

          BTW, I don't believe quota could have been involved in the failures you saw, since hourly/daily file transfer quota is 500MB / 1000MB . Also I recall over-limit is explicitly reported in FM's FTP.

          > They have reproduced the errors I saw and are looking into it,
          > and they've said they're working on a new implementation

          They've told me changes have been made. Since then, no failures here.

          Thanks Craig and sorry to have consumed your time on a false alarm.

          Comment


          • #6
            Originally posted by chrisjj View Post
            BTW, I don't believe quota could have been involved in the failures you saw, since hourly/daily file transfer quota is 500MB / 1000MB . Also I recall over-limit is explicitly reported in FM's FTP.
            I didn't mean to imply that they were related; I just ran into the quota early in my testing, so I wasn't able to investigate it thoroughly when you first reported the issue. Once that happened any uploads returned "Quota exceeded", so it was obvious what it happened.

            I wasn't uploading that large of files, so I don't think I hit 500MB, but it was only a temporary setback either way.
            ZoŽ P Scooter Software

            Comment


            • #7
              > Once that happened any uploads returned "Quota exceeded", so it was
              > obvious what it happened. I wasn't uploading that large of files, so I
              > don't think I hit 500MB

              That's a mystery, since I see no FM account type having FTP has an hourly limit below 500Mb.

              Comment

              Working...
              X