mongrel unicorn - Jul 2010 - Problem with x-www-form-urlencoded

Howdy all,

I''m having a strange issue after moving from Thin to Unicon.  One of
the form values being posted is not showing up in our request, below you can see
a Rails log entry and notice that there is no parameter
''messageID'' but it shows in the
''action_dispatch.request.request_parameters'' collection.

Has anyone else seen this, and is there a solution?

Started POST "/smsGatewayClient/notifyMultimediaMessageDelivered" for
10.244.90.114 at Thu Jul 15 13:39:26 -0700 2010
  Processing by MessagesController#discovered as */*
  Parameters: {"deliveryResponse"=>"<?xml
version=\"1.0\"?>\r\n<env:Envelope
xmlns:env=\"http://schemas.xmlsoap.org/soap/envelope/\">\r\n<env:Header>\r\n<mm7:TransactionID
xmlns:mm7=\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\"
env:mustUnderstand=\"1\">0AB1A686B00E00002010000101</mm7:TransactionID>\r\n</env:Header>\r\n<env:Body>\r\n<DeliveryReportReq
xmlns=\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\">\r\n<MM7Version>6.8.0</MM7Version>\r\n<MessageID>0AB1A686B00E000020100001</MessageID>\r\n<Recipient>\r\n<Number>6178331496</Number>\r\n</Recipient>\r\n<Sender>\r\n<ShortCode>78000</ShortCode>\r\n</Sender>\r\n<Date>2010-07-15T20:38:55+00:00</Date>\r\n<MMStatus>Retrieved</MMStatus>\r\n<UACapabilities
UAProf=\"rim9530v1\"\r\n
TimeStamp=\"2010-07-15T20:38:55+00:00\"
/>\r\n</DeliveryReportReq>\r\n</env:Body>\r\n</env:Envelope>",
"destination"=>"tel:6178331496",
"method"=>"post",
"clientTransactionID"=>"21qb7g71m72i5l21ks6t85q3t5sc\">",
"serviceCode"=>"78000",
"outputState"=>"C",
"charset"=>"UTF-8\",
\"SERVER_PROTOCOL\"=>\"HTTP/1.0\",
\"action_dispatch.secret_token\"=>\"REDACTED\",
\"rack.run_once\"=>false, \"rack.version\"=>[1, 1],
\"SERVER_SOFTWARE\"=>\"Unicorn 1.1.2\",
\"PATH_INFO\"=>\"/smsGatewayClient/notifyMultimediaMessageDelivered\",
\"REMOTE_ADDR\"=>\"127.0.0.1\",
\"action_dispatch.request.path_parameters\"=>{:action=>\"index\",
:controller=>\"forward\",
:url=>\"notifyMultimediaMessageDelivered\"},
\"SCRIPT_NAME\"=>\"\",
\"action_dispatch.parameter_filter\"=>[:password],
\"rack.multithread\"=>false,
\"HTTP_VERSION\"=>\"HTTP/1.0\",
\"action_dispatch.request.request_parameters\"=>{\"deliveryResponse\"=>\"<?xml
version=\\\"1.0\\\"?>\\r\\n<env:Envelope
xmlns:env=\\\"http://schemas.xmlsoap.org/soap/envelope/\\\">\\r\\n<env:Header>\\r\\n<mm7:TransactionID
xmlns:mm7=\\\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\\\"
env:mustUnderstand=\\\"1\\\">0AB1A686B00E00002010000101</mm7:TransactionID>\\r\\n</env:Header>\\r\\n<env:Body>\\r\\n<DeliveryReportReq
xmlns=\\\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\\\">\\r\\n<MM7Version>6.8.0</MM7Version>\\r\\n<MessageID>0AB1A686B00E000020100001</MessageID>\\r\\n<Recipient>\\r\\n<Number>6178331496</Number>\\r\\n</Recipient>\\r\\n<Sender>\\r\\n<ShortCode>78000</ShortCode>\\r\\n</Sender>\\r\\n<Date>2010-07-15T20:38:55
00:00</Date>\\r\\n<MMStatus>Retrieved</MMStatus>\\r\\n<UACapabilities
UAProf=\\\"rim9530v1\\\"\\r\\n TimeStamp=\\\"2010-07-15T20:38:55
00:00\\\"
/>\\r\\n</DeliveryReportReq>\\r\\n</env:Body>\\r\\n</env:Envelope>\",
\"messageID\"=>\"1s2oqbn15s4j3t2jbsgft72ijqh9\",
\"destination\"=>\"tel:6178331496\",
\"clientTransactionID\"=>\"21qb7g71m72i5l21ks6t85q3t5sc\",
\"serviceCode\"=>\"78000\",
\"outputState\"=>\"C\"},
\"rack.request.form_vars\"=>\"messageID=1s2oqbn15s4j3t2jbsgft72ijqh9",
"#<struct Unicorn::TeeInput socket"=>"nil,
req={\"action_dispatch.request.formats\"=>[#<Mime::Type:0xb7476474
@synonyms=[\"application/xhtml xml\"], @symbol=:html,
@string=\"text/html\">],
\"action_dispatch.request.parameters\"=>{\"deliveryResponse\"=>\"<?xml
version=\\\"1.0\\\"?>\\r\\n<env:Envelope
xmlns:env=\\\"http://schemas.xmlsoap.org/soap/envelope/\\\">\\r\\n<env:Header>\\r\\n<mm7:TransactionID
xmlns:mm7=\\\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\\\"
env:mustUnderstand=\\\"1\\\">0AB1A686B00E00002010000101</mm7:TransactionID>\\r\\n</env:Header>\\r\\n<env:Body>\\r\\n<DeliveryReportReq
xmlns=\\\"http://www.3gpp.org/ftp/Specs/archive/23_series/23.140/schema/REL-6-MM7-1-4\\\">\\r\\n<MM7Version>6.8.0</MM7Version>\\r\\n<MessageID>0AB1A686B00E000020100001</MessageID>\\r\\n<Recipient>\\r\\n<Number>6178331496</Number>\\r\\n</Recipient>\\r\\n<Sender>\\r\\n<ShortCode>78000</ShortCode>\\r\\n</Sender>\\r\\n<Date>2010-07-15T20:38:55
00:00</Date>\\r\\n<MMStatus>Retrieved</MMStatus>\\r\\n<UACapabilities
UAProf=\\\"rim9530v1\\\"\\r\\n TimeStamp=\\\"2010-07-15T20:38:55
00:00\\\"
/>\\r\\n</DeliveryReportReq>\\r\\n</env:Body>\\r\\n</env:Envelope>\",
\"messageID\"=>\"1s2oqbn15s4j3t2jbsgft72ijqh9\",
\"destination\"=>\"tel:6178331496\",
\"sender\"=>\"6178331496\",
\"action\"=>\"index\",
\"url\"=>\"notifyMultimediaMessageDelivered\",
\"clientTransactionID\"=>\"21qb7g71m72i5l21ks6t85q3t5sc\",
\"serviceCode\"=>\"78000\",
\"outputState\"=>\"C\",
\"controller\"=>\"forward\"},
\"rack.session\"=>{\"session_id\"=>\"b059b627561cc047dd7ab3e7e8de0baf\"},
\"rack.logger\"=>#<Logger:0xb7a21590
@logdev=#<Logger::LogDevice:0xb7a214dc @shift_age=0,
@filename=\"log/unicorn.log\",
@mutex=#<Logger::LogDevice::LogDeviceMutex:0xb7a214b4 @mon_waiting_queue=[],
@mon_entering_queue=[], @mon_count=0, @mon_owner=nil>,
@dev=#<File:log/unicorn.log>, @shift_size=1048576>,
@formatter=#<Logger::SimpleFormatter:0xb6f3bcfc @datetime_format=nil>,
@level=0, @default_formatter=#<Logger::Formatter:0xb7a21504
@datetime_format=nil>, @progname=nil>,
\"SERVER_NAME\"=>\"cdngw.g8wave.com\",
\"HTTP_HOST\"=>\"cdngw.g8wave.com\",
\"action_dispatch.remote_ip\"=>#<ActionDispatch::RemoteIp::RemoteIpGetter:0xb703cb74
@trusted_proxies=/(^127\\.0\\.0\\.1$|^(10|172\\.(1[6-9]|2[0-9]|30|31)|192\\.168)\\.)/i,
@check_ip_spoofing=true, @env={...}>,
\"rack.url_scheme\"=>\"http\",
\"CONTENT_LENGTH\"=>\"1332\",
\"HTTP_USER_AGENT\"=>\"Jakarta Commons-HttpClient/3.0\",
\"HTTP_X_REAL_IP\"=>\"10.244.90.114\",
\"REQUEST_PATH\"=>\"/smsGatewayClient/notifyMultimediaMessageDelivered\",
\"action_dispatch.request.query_parameters\"=>{\"sender\"=>\"6178331496\"},
\"rack.errors\"=>#<File:log/unicorn.stderr.log>,
\"CONTENT_TYPE\"=>\"application/x-www-form-urlencoded"}

Eternally grateful,

R

Richard Penwell <almightylinuxgod at me.com>
wrote:
> Howdy all,
> I''m having a strange issue after moving from Thin to Unicon.  One
of
> the form values being posted is not showing up in our request, below
> you can see a Rails log entry and notice that there is no parameter
> ''messageID'' but it shows in the
> ''action_dispatch.request.request_parameters'' collection.
Hi Richard,  Which versions of Rails and Rack are you using?

There''s a chance Thin and Unicorn could be loading different
versions of Rack and we might be hitting a bug in one version
of Rack.
> Has anyone else seen this, and is there a solution?
I haven''t seen nor looked into this myself, but I''ve heard
some talk of
multipart oddness in the Rack mailing list

-- 
Eric Wong

So I discovered this was a problem whereby request.body.to_s behaves
differently.  I wonder if TeeStream should define to_s as an alias for read?

Sent from my iPhone

On Jul 15, 2010, at 6:14 PM, Eric Wong <normalperson at yhbt.net> wrote:
> Richard Penwell <almightylinuxgod at me.com> wrote:
>> Howdy all,
> 
>> I''m having a strange issue after moving from Thin to Unicon. 
One of
>> the form values being posted is not showing up in our request, below
>> you can see a Rails log entry and notice that there is no parameter
>> ''messageID'' but it shows in the
>> ''action_dispatch.request.request_parameters''
collection.
> 
> Hi Richard,  Which versions of Rails and Rack are you using?
> 
> There''s a chance Thin and Unicorn could be loading different
> versions of Rack and we might be hitting a bug in one version
> of Rack.
> 
>> Has anyone else seen this, and is there a solution?
> 
> I haven''t seen nor looked into this myself, but I''ve
heard some talk of
> multipart oddness in the Rack mailing list
> 
> -- 
> Eric Wong

Richard Penwell <almightylinuxgod at me.com>
wrote:
> So I discovered this was a problem whereby request.body.to_s behaves
> differently.  I wonder if TeeStream should define to_s as an alias for
> read?
to_s isn''t defined by any version of the Rack spec.

It''s horrible practice to use it, too, since it could be a big upload
that uses all your memory.

What are you using that does request.body.to_s?  Can you change it?

-- 
Eric Wong

We have an application that forwards requests to staging, dev or production.  So
it takes the body of the request and forwards it along...

Sent from my iPhone

On Jul 15, 2010, at 6:40 PM, Eric Wong <normalperson at yhbt.net> wrote:
> Richard Penwell <almightylinuxgod at me.com> wrote:
>> So I discovered this was a problem whereby request.body.to_s behaves
>> differently.  I wonder if TeeStream should define to_s as an alias for
>> read?
> 
> to_s isn''t defined by any version of the Rack spec.
> 
> It''s horrible practice to use it, too, since it could be a big
upload
> that uses all your memory.
> 
> What are you using that does request.body.to_s?  Can you change it?
> 
> -- 
> Eric Wong

Richard Penwell <almightylinuxgod at me.com>
wrote:
> On Jul 15, 2010, at 6:40 PM, Eric Wong <normalperson at yhbt.net>
wrote:
> > Richard Penwell <almightylinuxgod at me.com> wrote:
> >> So I discovered this was a problem whereby request.body.to_s
behaves
> >> differently.  I wonder if TeeStream should define to_s as an alias
for
> >> read?
> > 
> > to_s isn''t defined by any version of the Rack spec.
> > 
> > It''s horrible practice to use it, too, since it could be a
big upload
> > that uses all your memory.
> > 
> > What are you using that does request.body.to_s?  Can you change it?
> > 
> We have an application that forwards requests to staging, dev or
> production.  So it takes the body of the request and forwards it
> along...
(top-posting corrected)

I would always make it use a read/write loop with some fixed chunk size.

If you don''t care about memory usage or if you have nginx properly
configured to reject large requests (the default of 1M is actually quite
reasonable), then use "request.body.read" instead since
that''s the
supported way to use all Rack apps/middlewares.  You can try your apps
with Rack::Lint middleware loaded during development/testing to catch
these things.

-- 
Eric Wong

I have used request.body.read as it''s only a HTTP form post from an
external provider of a fixed size.

Thank you so much, I suppose I figured it out when I noticed that most of those
quotes were escaped...

R

On Jul 16, 2010, at 3:54 AM, Eric Wong wrote:
> Richard Penwell <almightylinuxgod at me.com> wrote:
>> On Jul 15, 2010, at 6:40 PM, Eric Wong <normalperson at yhbt.net>
wrote:
>>> Richard Penwell <almightylinuxgod at me.com> wrote:
>>>> So I discovered this was a problem whereby request.body.to_s
behaves
>>>> differently.  I wonder if TeeStream should define to_s as an
alias for
>>>> read?
>>> 
>>> to_s isn''t defined by any version of the Rack spec.
>>> 
>>> It''s horrible practice to use it, too, since it could be a
big upload
>>> that uses all your memory.
>>> 
>>> What are you using that does request.body.to_s?  Can you change it?
>>> 
>> We have an application that forwards requests to staging, dev or
>> production.  So it takes the body of the request and forwards it
>> along...
> 
> (top-posting corrected)
> 
> I would always make it use a read/write loop with some fixed chunk size.
> 
> If you don''t care about memory usage or if you have nginx properly
> configured to reject large requests (the default of 1M is actually quite
> reasonable), then use "request.body.read" instead since
that''s the
> supported way to use all Rack apps/middlewares.  You can try your apps
> with Rack::Lint middleware loaded during development/testing to catch
> these things.
> 
> -- 
> Eric Wong