Error binding should include response / 400 MalformedPOSTRequest on S3

[braindeaf]

I've been using plupload for a few weeks now and I've managed to hook it up to upload our files directly to S3 which is great. However we realised that some files are not being saved on S3 the response from Amazon from their logs shows for some clients 400 MalformedPOSTRequest. This is probably less than 1% but that's still significant.

The problem is that if users upload files and that fails we have no way of knowing (without replicating the error ourselves with the exact file and exact set up as them, which is tricky and we haven't managed to replicate an error even once). My next thought was we could post the error response to our server everytime this happens so we could debug the error without having to get the user to investigate their JS console looking for it.

Forcing an error from our side we can see that the response body is not included in the error which would be really handy. 'HTTP Error' is all we get.

Object {code: -200, message: "HTTP Error.", file: g.File, status: 403}

The 'FileUploaded' callback supports the response uploader.bind 'FileUploaded', (up, file, response) ->

However, 'Error' does not. uploader.bind 'Error', (up, error) ->

While this might not solve our problem we'd like to see if there is a more detailed error in the response body from Amazon and if that points to a further problem within plupload.

[jayarjo]

The problem here is that depending on the runtime you might not even get a response body when status code is error. Are you on stable 1.x branch?

Does Amazon log only status, or the whole erroneous POST body?

[braindeaf]

To be honest I'm a bit worried that the response body will actually be empty anyway :(. I'm using 1.5.7 at the moment which I pushed out today. I'll keep an eye to see if any new failures come in today.

Not sure about the Amazon logs to be honest, it would be nice to see the actually post body in this instance from their side. Their logs appear to be a pretty standard combined log format. I'll do some more research.

[jayarjo]

I'm asking because 400 MalformedPOSTRequest is already kinda informative and there could be nothing else in the response anyway. What can help, could be an actual body of such malformed request.

From Error Responses:

MalformedPOSTRequest - The body of your POST request is not well-formed multipart/form-data.

Could you post Plupload config that you use?

[braindeaf]

Thanks for your time on this, I hope it is an interesting puzzle.

This is probably overkill because we make changes to the upload settings as we go, but I'll explain the process we take in case anything we're doing along the way rings any bells.

We initialize our uploader to begin with for the most part single queue, filtering a few file types, allowing multiselection, etc. In order to upload to S3 in the correct location we create an asset on our server and pass back the relavent S3 policy pointing to the correct key say 'assets/000/000/001/original.wav'. We initialize the upload and make an ajax call in 'BeforeUpload' to create the asset on our server, this returns an asset object and S3 policy as JSON.

We overwrite the name of the uploading file 'name' and 'Filename' with something like 'asset_001' because non-ascii UTF-8 characters get messed up being passed as a JSON string (and subsequently no longer match the S3 policy) and we have to supply both 'name' and 'Filename' in the post and the S3 policy because of Flash on IE seems to post both which blocked us for a while. We set the additional parameters for the S3 policy and call up.trigger('UploadFile', file)

In terms of grabbing the post body it seems impossible to log on Amazon, it would be pretty huge anyway, and only the uploader itself will be able give us the body its posting to S3. I wish we could replicate this ourselves as I'd have much more to go on.

  s3                = div.data('s3') == true
  upload_url        = div.data('s3-uploader')
  update            = div.data('uploader-update')
  file_types        = div.data('uploader-file-types')
  filter_file_types = div.data('uploader-filter-file-types') || true
  browse_button     = div.data('browse-button')
  method            = div.data('uploader-method') || 'post'
  multi_selection   = !div.data('uploader-single-file')
  controls          = $('#' + div.data('uploader-controls'))
  filter_file_types = div.data('uploader-filter-file-types')

  if ($.type(div.data('filelist')) == 'string' && div.data('filelist').slice(-2) == ' >')
    append_to_filelist = true
    filelist           = $(div.data('filelist').slice(0,-2))
  else
    append_to_filelist = false
    filelist           = $(div.data('filelist'))

  if filelist.eq(0).length == 0
    filelist = div.find('ul.filelist')

  uploader = new plupload.Uploader
    url      : upload_url
    runtimes : 'html5,flash'
    browse_button : controls.find('button.browse').attr('id') || 'browse'
    container: controls.attr('id')
    max_file_size : '1024mb'
    multiple_queues: false
    multi_selection: multi_selection
    flash_swf_url : '/swfs/plupload.flash.swf'

  # filter files by type
  if filter_file_types != false
    uploader.settings.filters = [{title : 'Supported files ('  + file_types + ')', extensions: file_types}]

  # initialize uploader
  uploader.init()
  # Init event
  # uploader.bind 'Init', (up, params) -> 

  # FilesAdded event
  uploader.bind 'FilesAdded', (up, files) ->

    removed_files = []

    for file in files
      unless file.name.match(RegExp('^.+\.(' + file_types.split(',').join('|') + ')$'))
        removed_files.push(uploader.removeFile(file).name)

    if removed_files.length > 0
      $.flash('error', 'Unsupported file types: ' + removed_files.join(', '))

    for file in files
      unless (file.name in removed_files)
        s = '<li id="' + file.id + '" data-is-uploading><div class="file"><span class="filename">' + file.name + ' (' + plupload.formatSize(file.size) + ')</span><span class="status">queued for upload</span></div></li>'
        if append_to_filelist
          filelist.append(s)
        else
          filelist.html(s)

    # autostart upload
    if uploader.state == plupload.STOPPED
      setTimeout -> 
        uploader.start()
      , 500

  # StateChanged event
  # uploader.bind 'StateChanged', (up) -> 

  # BeforeUpload event
  #
  # S3
  #
  if s3
    $.log('S3 uploader')
    uploader.bind 'BeforeUpload', (up, file) ->
      $.flash('notice', "Uploading '" + file.name + "'")
      $.ajax
        url  : upload_url,
        data : 
          s3_upload : true,
          file_name : file.name
        dataType : 'json'
        type : method
        success : (data) ->
          upload = data['upload']
          file.update_url = data.update_url
          # set s3 specific settings
          up.settings.url = upload.host
          up.settings.multipart =  true
          up.settings.multipart_params = 
            'name'                  : upload.name
            'Filename'              : upload.name
            'key'                   : upload.key
            'acl'                   : upload.acl
            'success_action_status' : upload.success_action_status
            'AWSAccessKeyId'        : upload.aws_key
            'policy'                : upload.policy
            'signature'             : upload.signature

          up.settings.file_data_name  = 'file'
          up.settings.multiple_queues = true
          # s3 settings (end)
          # force UploadFile;
          up.refresh()
          up.trigger('UploadFile', file)
        error : (xhr, status, body) ->
          $.flash('error', 'An error occurred')
          # uploader.stop()

      # return false so async call can finish first
      return false

  # UploadProgress event
  uploader.bind 'UploadProgress', (up, file) ->
    filelist.find('li#' + file.id + ' span.status').html('uploading ' + file.percent + '%')

  # FileUploaded event
  uploader.bind 'FileUploaded', (up, file, response) -> 
    $.log('file uploaded')
    if ! s3
      asset = JSON.parse(response.response)
      file.update_url = asset.update_url

    filelist.find('li#' + file.id + ' span.status').html('uploaded ' + file.percent + '%')
    $.ajax
      url       : file.update_url,
      type      : 'PUT',
      dataType  : 'html',
      success   : (data) ->
        # if no 'update' replace list item with new asset item
        unless update
          filelist.find('li#' + file.id).replaceWith(data)

        if ($.type(update) == 'string' && update.slice(-2) == ' >')
          $(update.slice(0,-2)).append(data);
        else
          $(update).html(data)
        filelist.find('li#' + file.id + ' span.status').html('completed')
      error     : (data) -> 
        filelist.find('li#' + file.id + ' span.status').html('error')
        uploader.stop()

  # Error event
  uploader.bind 'Error', (up, error) ->
    $.flash('error', error.message)
    new Pledge.Error(error.message, [error.file.name, error.file.update_url].join("\n"))

  # UploadComplete event
  # uploader.bind 'UploadComplete', (up, files) ->

[braindeaf]

I hope coffeescript isn't a pain.

[jayarjo]

No chunking, no client-resizing... hm... seems like Plupload is using native upload methods for both html5, and flash. For some reason though I think this should be flash failing. Anyway, this is bad, as default upload methods can't be affected in any way...

Do you got any additional details, like the browser type and version where failure was detected? or have the file that failed? Do you know if failed file ever uploaded successfully afterwards?