503 Bad Sequence of Commands Issue

[gkontos]

I had this problem when transferring files to a filezilla server. I saw the following within the server logs:

> stor /include/header.html
> 150 Opening data channel for file upload to server of "/include/header.html"
> pasv
> 227 Entering Passive Mode (10,53,40,63,197,233)
> 226 Successfully transferred ""
> stor /index.html
> 503 Bad sequence of commands.

This happens more or less randomly. I was able to fix this issue by changing the processFile function in ftp_push.js to include an additional PASV command :

var processFile = function processFile (err) {
      if (err) {
        grunt.log.warn(messages.fileTransferFail(file.dest, err));
      } else {
        grunt.log.ok(messages.fileTransferSuccess(file.dest));
      }

      ++index;
      // If there are more files, then keep pushing
      if (index < files.length) {
        file = files[index];
     // additonal pasv command to ensure that the server is ready to receive put command.
        server.raw.pasv(function(err,data) {
         grunt.log.ok('code ' + data.code);
       });
        server.put(grunt.file.read(file.src, { encoding: null }), file.dest, processFile);

      }
...

[Robert-W]

Hey sorry for the late reply, Ive been out with the Flu for the last week. I though JSFTP was doing that automatically in versions after 1.5.1 but if not then maybe I need to add it in, this is the first time I have seen that one before.

Could you possibly run it in debug mode, using debug: true in your options and paste that info here?

[gkontos]

No sweat. Thanks for looking into it. The output below is from version 0.4.3 of grunt-ftp-push.

�[4mRunning "ftp_push:test" (ftp_push) task�[24m
DEBUG: user_command"user webdev"DEBUG: event:connect{}DEBUG: response{
"code": 220,
"text": "220-FileZilla Server 0.9.53 beta\n220 srv200",
"isMark": false,
"isError": false
}DEBUG: response{
"code": 331,
"text": "331 Password required for webdev",
"isMark": false,
"isError": false
}DEBUG: user_command"pass xxxxxx"DEBUG: response{
"code": 230,
"text": "230 Logged on",
"isMark": false,
"isError": false
}DEBUG: user_command"type I"DEBUG: response{
"code": 200,
"text": "200 Type set to I",
"isMark": false,
"isError": false
}�[32m>> �[39mwebdev successfully authenticated!
DEBUG: user_command"mkd /content"DEBUG: response{
"code": 550,
"text": "550 Directory already exists",
"isMark": false,
"isError": true
}DEBUG: user_command"mkd /css"DEBUG: response{
"code": 550,
"text": "550 Directory already exists",
"isMark": false,
"isError": true
}DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,195)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/404.html"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 503,
"text": "503 Bad sequence of commands.",
"isMark": false,
"isError": true
}�[31m>> �[39m/content/404.html failed to transfer because Error: 503 Bad sequence of commands.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,135)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/about.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/about.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/about.html transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,114)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/batchView.html"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 503,
"text": "503 Bad sequence of commands.",
"isMark": false,
"isError": true
}�[31m>> �[39m/content/batchView.html failed to transfer because Error: 503 Bad sequence of commands.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,30)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/home.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/home.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/home.html transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,170)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /templates/dirPagination.tpl.html"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 503,
"text": "503 Bad sequence of commands.",
"isMark": false,
"isError": true
}�[31m>> �[39m/templates/dirPagination.tpl.html failed to transfer because Error: 503 Bad sequence of commands.
DEBUG: user_command"quit"DEBUG: response{
"code": 221,
"text": "221 Goodbye",
"isMark": false,
"isError": false
}�[32m>> �[39mFTP connection closed!

�[32mDone, without errors.�[39m

[gkontos]

The following output is what I see if I add an additional pasv command before the stor command.

�[4mRunning "ftp_push:test" (ftp_push) task�[24m
DEBUG: user_command"user webdev"DEBUG: event:connect{}DEBUG: response{
"code": 220,
"text": "220-FileZilla Server 0.9.53 beta\n220 srv200",
"isMark": false,
"isError": false
}DEBUG: response{
"code": 331,
"text": "331 Password required for webdev",
"isMark": false,
"isError": false
}DEBUG: user_command"pass xxxx"DEBUG: response{
"code": 230,
"text": "230 Logged on",
"isMark": false,
"isError": false
}DEBUG: user_command"type I"DEBUG: response{
"code": 200,
"text": "200 Type set to I",
"isMark": false,
"isError": false
}�[32m>> �[39mwebdev successfully authenticated!
DEBUG: user_command"mkd /content"DEBUG: response{
"code": 550,
"text": "550 Directory already exists",
"isMark": false,
"isError": true
}DEBUG: user_command"mkd /css"DEBUG: response{
"code": 550,
"text": "550 Directory already exists",
"isMark": false,
"isError": true
}DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,249)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /cmdout.txt"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/cmdout.txt"",
"isMark": true,
"isError": false
}�[32m>> �[39m/cmdout.txt transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,134)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,176)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /cmdout2.txt"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/cmdout2.txt"",
"isMark": true,
"isError": false
}�[32m>> �[39m/cmdout2.txt transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,92)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,197,116)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /cmdout3.txt"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/cmdout3.txt"",
"isMark": true,
"isError": false
}�[32m>> �[39m/cmdout3.txt transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,173)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,197,232)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/404.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/404.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/404.html transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,197,143)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,199,37)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/about.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/about.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/about.html transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,197,54)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,197,153)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/batchView.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/batchView.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/batchView.html transferred successfully.
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,195,150)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,196,207)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /content/home.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/content/home.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/content/home.html transferred successfully.
...
DEBUG: user_command"pasv"DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,136)",
"isMark": false,
"isError": false
}�[32m>> �[39mcode 227
DEBUG: user_command"pasv"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred """,
"isMark": false,
"isError": false
}DEBUG: response{
"code": 227,
"text": "227 Entering Passive Mode (xx.xx.xx.xx,198,55)",
"isMark": false,
"isError": false
}DEBUG: user_command"stor /templates/dirPagination.tpl.html"DEBUG: response{
"code": 150,
"text": "150 Opening data channel for file upload to server of "/templates/dirPagination.tpl.html"",
"isMark": true,
"isError": false
}�[32m>> �[39m/templates/dirPagination.tpl.html transferred successfully.
DEBUG: user_command"quit"DEBUG: response{
"code": 226,
"text": "226 Successfully transferred "/templates/dirPagination.tpl.html"",
"isMark": false,
"isError": false
}DEBUG: response{
"code": 221,
"text": "221 Goodbye",
"isMark": false,
"isError": false
}�[32m>> �[39mFTP connection closed!

�[32mDone, without errors.�[39m

[Robert-W]

Thanks man, Ill look over these when I have some spare time and will probably submit a ticket to JSFTP about this with these logs and see if Sergei(maintainer of JSFTP) has any ideas. In the meantime, If it works with the extra passive command then keep using it and I will try to push an update soon with that command in there. Thanks again.

[gkontos]

Thanks. I did chime in on a similar ticket with jsftp, sergi/jsftp#118 (comment) .