Skip to content
This repository has been archived by the owner. It is now read-only.

Exception ArgumentError in Rack application object (invalid %-encoding) #21

Closed
floehopper opened this issue Jun 22, 2016 · 6 comments

Comments

Projects
None yet
1 participant
@floehopper
Copy link
Member

commented Jun 22, 2016

When this Harmonia task was first assigned, it looks as if the following exception occurred:

App 17414 stderr: [ 2016-06-21 03:16:09.9431 17431/0x000000023bdfb0(Worker 1) utils.rb:84 ]: *** Exception ArgumentError in Rack application object (invalid %-encoding ({"assignment":{"key":"2bxnid","created_at":"2016-06-21T04:16:06.949+01:00","task":{"key":"6t467a","name":"3CA end of year adjustments 2014","instructions":"---------- Forwarded message ----------\r\nFrom: Team at Proactive \u003cteam@proactive.uk.net\u003e\r\nDate: 21 June 2016 at 03:46\r\nSubject: Re: 3CA end of year adjustments 2014\r\nTo: Go Free Range Ltd \u003ceveryone@gofreerange.com\u003e\r\n\r\n\r\nHi James\r\n\r\n\r\n\r\nThanks for your feedback on the phone on Friday and for letting me\r\nhave the summary page relating to the 3CA journal. It doesn’t shed\r\nmuch light on things, and simply confirms what we said verbally. The\r\nfigure of £1,518.10 is the resultant VAT from a more detailed\r\ncalculation which (based on your document “3CA end of year adjustments\r\n2014.pdf”) probably included:\r\n\r\n\r\n\r\nA bit of output VAT on extra sales of 50.65\r\nA bit of input VAT on extra expenses of 1212.02\r\n\r\n\r\n\r\nAnd because 20% of those amounts doesn’t help me . . .  –10.13 +\r\n242.40 )) (process 17431, thread 0x000000023bdfb0(Worker 1)):
App 17414 stderr:       from /usr/lib/ruby/2.1.0/uri/common.rb:901:in `decode_www_form_component'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:42:in `unescape'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `block (2 levels) in parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `map'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `block in parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:104:in `each'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:104:in `parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/request.rb:375:in `parse_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/request.rb:213:in `POST'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/methodoverride.rb:26:in `method_override'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/methodoverride.rb:14:in `call'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/sinatra-1.4.5/lib/sinatra/base.rb:180:in `call'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/sinatra-1.4.5/lib/sinatra/base.rb:2014:in `call'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
[Tue Jun 21 03:16:09.943673 2016] [core:error] [pid 10100:tid 140391105902336] [client 178.79.161.133:34930] End of script output before headers: harmonia
@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 22, 2016

I've confirmed the above by re-assigning the task in Harmonia. I saw the following output in /var/log/apache2/error.log:

App 17414 stderr: [ 2016-06-22 12:54:01.4158 17431/0x000000023bdfb0(Worker 1) utils.rb:84 ]: *** Exception ArgumentError in Rack application object (invalid %-encoding ({"assignment":{"key":"dsettu","created_at":"2016-06-22T13:53:59.938+01:00","task":{"key":"6t467a","name":"3CA end of year adjustments 2014","instructions":"---------- Forwarded message ----------\r\nFrom: Team at Proactive \u003cteam@proactive.uk.net\u003e\r\nDate: 21 June 2016 at 03:46\r\nSubject: Re: 3CA end of year adjustments 2014\r\nTo: Go Free Range Ltd \u003ceveryone@gofreerange.com\u003e\r\n\r\n\r\nHi James\r\n\r\n\r\n\r\nThanks for your feedback on the phone on Friday and for letting me\r\nhave the summary page relating to the 3CA journal. It doesn’t shed\r\nmuch light on things, and simply confirms what we said verbally. The\r\nfigure of £1,518.10 is the resultant VAT from a more detailed\r\ncalculation which (based on your document “3CA end of year adjustments\r\n2014.pdf”) probably included:\r\n\r\n\r\n\r\nA bit of output VAT on extra sales of 50.65\r\nA bit of input VAT on extra expenses of 1212.02\r\n\r\n\r\n\r\nAnd because 20% of those amounts doesn’t help me . . .  –10.13 +\r\n242.40 )) (process 17431, thread 0x000000023bdfb0(Worker 1)):
App 17414 stderr:       from /usr/lib/ruby/2.1.0/uri/common.rb:901:in `decode_www_form_component'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:42:in `unescape'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `block (2 levels) in parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `map'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:105:in `block in parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:104:in `each'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/utils.rb:104:in `parse_nested_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/request.rb:375:in `parse_query'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/request.rb:213:in `POST'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/methodoverride.rb:26:in `method_override'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/rack-1.5.4/lib/rack/methodoverride.rb:14:in `call'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/sinatra-1.4.5/lib/sinatra/base.rb:180:in `call'
App 17414 stderr:       from /home/webhooks/app/vendor/gems/ruby/2.1.0/gems/sinatra-1.4.5/lib/sinatra/base.rb:2014:in `call'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
App 17414 stderr:       from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
[Wed Jun 22 12:54:01.416608 2016] [core:error] [pid 10100:tid 140391311050496] [client 178.79.161.133:42795] End of script output before headers: harmonia
@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 22, 2016

I've worked around this issue by editing the body of the Harmonia task and replacing the only occurrence of "%" with "percent" and then re-assigning the task. A new Trello card has now successfully been created.

@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 22, 2016

I believe the original exception is related to the discussion on this Rack issue.

@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 26, 2016

I've just reproduced this exception using a new action:

  post '/percent' do
    json = request.body.read
    attributes = JSON.parse(json)
    [200, attributes.inspect]
  end

And sending the following POST request:

curl -X POST -d '{"percent": "%"}' http://localhost:9292/percent
# => ArgumentError: invalid %-encoding ({"percent": "%"})

I then noticed this related issue and discovered that setting a content-type header to JSON avoided the exception being raised:

curl -X POST -H 'Content-Type:application/json' -d '{"percent": "%"}' http://localhost:9292/percent
# => {"percent"=>"%"}

In fact it turns out that setting the content type to application/x-www-form-urlencoded or empty string also leads to the exception being raised:

curl -X POST -H 'Content-Type:application/x-www-form-urlencoded' -d '{"percent": "%"}' http://localhost:9292/percent
# => ArgumentError: invalid %-encoding ({"percent": "%"})
curl -X POST -H 'Content-Type:' -d '{"percent": "%"}' http://localhost:9292/percent
# => ArgumentError: invalid %-encoding ({"percent": "%"})

I think my conclusion is that Harmonia probably isn't setting a content-type header, but ought to be.

Having said that, I think we can reasonably assume that all requests to this app are currently expected to have a JSON content-type, so I'm going to investigate adding some custom middleware to inject this header as suggested in this comment.

/cc @lazyatom

@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 26, 2016

Note that my fix is to force the content type of all incoming requests to be application/json. This isn't ideal and should be removed if Harmonia starts sending the correct header.

@floehopper

This comment has been minimized.

Copy link
Member Author

commented Jun 28, 2016

I've been in touch with James and he's just deployed a fix which should set the Content-Type header correctly, so we could probably remove my bodge.

floehopper added a commit that referenced this issue Sep 2, 2016

Revert "Force Content-Type of incoming requests to application/json"
This reverts commit 1fb3674.

About 9 weeks ago, James A said he'd fixed this problem in Harmonia, so it
should be safe to remove this bodge.

See #21 for details.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.