Hello, I have run into the following situation several times in the past few months: (My stack is Nginx -- Unicorn -- Rails 3.0.12) 1. Client clicks a delete link in my webapp. 2. Rails starts processing the appropriate destroy action. This updates various things in the database (but not in a single db transaction). 3. Client terminates the connection. 4. Rails stops executing the destroy action wherever it has got to, leaving the latter part of the action unexecuted and my db inconsistent. 5. Rails and Unicorn don''t write anything to their logs; Nginx writes a 499. This question has been asked before[1] but regrettably I don''t entirely understand all the solutions proposed :) I plan to wrap all the changes made by my destroy action in a single db transaction. I''m assuming this will ensure db consistency, even when subject to awkward clients. Is that correct? (I''ll probably also move the action''s work onto a background process, e.g. with delayed job.) Now apologies if I''m barking up the wrong tree here...in general is it possible to configure Unicorn to buffer the request and: - if the client terminates before the request is fully received, don''t pass it to Rails at all; - else pass the complete request to Rails and let Rails execute it fully, even if client terminates in the meantime? The thread[1] also mentioned Nginx''s proxy_ignore_client_abort. If that''s relevant, has anyone tried it? [1] http://rubyforge.org/pipermail/mongrel-unicorn/2011-August/001096.html Many thanks, Andrew Stewart
Andrew Stewart <boss at airbladesoftware.com> wrote:> Hello, > > I have run into the following situation several times in the past few months: > > (My stack is Nginx -- Unicorn -- Rails 3.0.12) > > 1. Client clicks a delete link in my webapp. > 2. Rails starts processing the appropriate destroy action. This updates various things in the database (but not in a single db transaction). > 3. Client terminates the connection. > 4. Rails stops executing the destroy action wherever it has got to, leaving the latter part of the action unexecuted and my db inconsistent. > 5. Rails and Unicorn don''t write anything to their logs; Nginx writes a 499. > > This question has been asked before[1] but regrettably I don''t > entirely understand all the solutions proposed :) > > I plan to wrap all the changes made by my destroy action in a single > db transaction. I''m assuming this will ensure db consistency, even > when subject to awkward clients. Is that correct?Yes (assuming all your DB actions in the transaction may be rolled-back). I''m no expert in DBs, but I recommend you always use transactions when data consistency is required.> (I''ll probably also move the action''s work onto a background process, > e.g. with delayed job.)This also works, too, and is likely better if your DB actions take a long time.> Now apologies if I''m barking up the wrong tree here...in general is it > possible to configure Unicorn to buffer the request and: > > - if the client terminates before the request is fully received, don''t > pass it to Rails at all; > - else pass the complete request to Rails and let Rails execute it > fully, even if client terminates in the meantime?Yes. Using the Unicorn::PrereadInput middleware (before Rails or any other middleware/framework touches env["rack.input"]) should do everything you want.> The thread[1] also mentioned Nginx''s proxy_ignore_client_abort. If > that''s relevant, has anyone tried it?I haven''t, perhaps Jesse can respond?> [1] > http://rubyforge.org/pipermail/mongrel-unicorn/2011-August/001096.htmlOn a related note, Tom Burns has/had the same problem[2]. Unlike you, he wanted to avoid processing the request in as many cases as possible. The solution he came up with isn''t 100% foolproof, either, but his primary goal was to reduce load on an overloaded system. I haven''t heard back on results of our nasty/crazy solution, though. If you do combine Tom''s solution with yours, you still need to ensure DB consistency in the app. [2] http://mid.gmane.org/CAK4qKG32dGgNbzTzCb6NoH5hu_DrHMOFaFhk-6Xvy-T86++ukA at mail.gmail.com
On 28 Nov 2012, at 22:10, Eric Wong wrote:> Yes. Using the Unicorn::PrereadInput middleware (before Rails or any > other middleware/framework touches env["rack.input"]) should do > everything you want.Excellent. This isn''t enabled by default so I wonder whether there any disadvantages or side-effects one should be aware of? Yours, Andrew Stewart
Andrew Stewart <boss at airbladesoftware.com> wrote:> On 28 Nov 2012, at 22:10, Eric Wong wrote: > > Yes. Using the Unicorn::PrereadInput middleware (before Rails or > > any other middleware/framework touches env["rack.input"]) should do > > everything you want. > > Excellent. > > This isn''t enabled by default so I wonder whether there any > disadvantages or side-effects one should be aware of?It''ll be slower for fast clients doing large uploads (as it leads to flushing of the page cache to stable storage). For small uploads/POST requests (normal web browser stuff), it likely won''t matter. Keep in mind nginx basically does what PrereadInput does on its end, too. Now, for Rack apps that deal with raw PUT requests (from "curl -T" on a LAN) several gigabytes large: Buffering a large request up front means the data could be out of the kernel page cache by the time an application sees it. As a result, the application is will trigger additional disk seeks to reread the data it buffered. With the default streaming/lazy-buffering (TeeInput), unicorn reads data off the socket as your application needs it. This means the data your app sees is still "hot" in memory, and won''t have to wait for disk (or even slower memory accesses). All the writes to the (rewindable) temporary file are still buffered by the OS to $TMPDIR, but those disk writes are usually asynchronous and minimally affects application processing time. unicorn also supports "rewindable_input false" in its config. This violates the Rack 1.x spec, but it allows applications which process a data stream to avoid generating any disk I/O at all. No filesystem/disk limitations to worry about at all here, one could stream petabytes of data through unicorn this way.
On 29 Nov 2012, at 10:17, Eric Wong wrote:> [snip]Thanks for all the information. Cheers, Andrew Stewart
2012/11/28 Andrew Stewart <boss at airbladesoftware.com>:> 1. Client clicks a delete link in my webapp. > 2. Rails starts processing the appropriate destroy action. This updates various things in the database (but not in a single db transaction). > 3. Client terminates the connection. > 4. Rails stops executing the destroy action wherever it has got to, leaving the latter part of the action unexecuted and my db inconsistent. > 5. Rails and Unicorn don''t write anything to their logs; Nginx writes a 499.Hi, I''ve read the thread and understood that there is solutions or workarounds for this issue. However I don''t understand why this issue does exist. There should be no relationship between the TCP connection and the request processing: - If the request has been entirely received, the process it entirely, period. - If later the response cannot be sent due to connection closed, then ok, the response cannot be sent, period. I don''t understand why the application on top of the HTTP/TCP layer (so the Rails app) should be interrupted because the TCP connection is closed prematurely. The HTTP layer (which involves a single TCP connection for each HTTP request/response pair) is a layer below the application layer, should not disturb the Rails app IMHO. Is this a design issue of Rails? -- I?aki Baz Castillo <ibc at aliax.net>
2012/11/29 I?aki Baz Castillo <ibc at aliax.net>:> - If the request has been entirely received, the process it entirely, period.I mean: - If the request has been entirely received, theN process it entirely, period. -- I?aki Baz Castillo <ibc at aliax.net>
I?aki Baz Castillo <ibc at aliax.net> wrote:> 2012/11/28 Andrew Stewart <boss at airbladesoftware.com>: > > 1. Client clicks a delete link in my webapp. > > 2. Rails starts processing the appropriate destroy action. This updates various things in the database (but not in a single db transaction). > > 3. Client terminates the connection. > > 4. Rails stops executing the destroy action wherever it has got to, leaving the latter part of the action unexecuted and my db inconsistent. > > 5. Rails and Unicorn don''t write anything to their logs; Nginx writes a 499. > > Hi, I''ve read the thread and understood that there is solutions or > workarounds for this issue. However I don''t understand why this issue > does exist. There should be no relationship between the TCP connection > and the request processing: > > - If the request has been entirely received, the process it entirely, period. > - If later the response cannot be sent due to connection closed, then > ok, the response cannot be sent, period. > > I don''t understand why the application on top of the HTTP/TCP layer > (so the Rails app) should be interrupted because the TCP connection is > closed prematurely. The HTTP layer (which involves a single TCP > connection for each HTTP request/response pair) is a layer below the > application layer, should not disturb the Rails app IMHO. > > Is this a design issue of Rails?I suspect the the only possibility is when Rails is reading the multipart response in a largish upload (any upload request which can''t fit in socket buffers). Perhaps Andrew can enlighten us further.
On 30 Nov 2012, at 00:04, Eric Wong wrote:> I?aki Baz Castillo <ibc at aliax.net> wrote: >> I don''t understand why the application on top of the HTTP/TCP layer >> (so the Rails app) should be interrupted because the TCP connection is >> closed prematurely. The HTTP layer (which involves a single TCP >> connection for each HTTP request/response pair) is a layer below the >> application layer, should not disturb the Rails app IMHO. >> >> Is this a design issue of Rails? > > I suspect the the only possibility is when Rails is reading the > multipart response in a largish upload (any upload request which > can''t fit in socket buffers).On the three occasions I''ve had this problem it''s been a tiny request. The user clicks an ordinary Rails delete link. This POSTs to a URL with two parameters: an authenticity token and the _method. The corresponding destroy action looks like: def destroy client = Client.find params[:id] # 1 (ignores soft-deleted records) client.soft_delete # 2 (sets a deleted_at timestamp) client.brands.each(&:destroy) # 3 (a client has many brands) redirect_to clients_path end Nginx logged: x.xxx.xx.xx - - [27/Nov/2012:14:40:28 +0000] "POST /clients/2248 HTTP/1.1" 499 0 "https://example.com/clients/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" x.xxx.xx.xx - - [27/Nov/2012:14:40:29 +0000] "POST /clients/2248 HTTP/1.1" 404 592 "https://example.com/companies/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" You can see the first request was terminated by the user. Hot on its heels the user tried again and got a 404. The 404 was triggered by step 1 above: the first request had successfully soft-deleted the client. However the client''s brands were still in the database. The first request had executed steps 1 and 2 but not step 3. Unicorn didn''t log anything. Rails didn''t log the first request but did log the second. I understand the steps to mitigate the problem...but I remain confused about why the Rails app was interrupted because the TCP connection was closed prematurely. Yours, Andrew Stewart
Andrew Stewart <boss at airbladesoftware.com> wrote:> On 30 Nov 2012, at 00:04, Eric Wong wrote: > > I?aki Baz Castillo <ibc at aliax.net> wrote: > >> I don''t understand why the application on top of the HTTP/TCP layer > >> (so the Rails app) should be interrupted because the TCP connection is > >> closed prematurely. The HTTP layer (which involves a single TCP > >> connection for each HTTP request/response pair) is a layer below the > >> application layer, should not disturb the Rails app IMHO. > >> > >> Is this a design issue of Rails? > > > > I suspect the the only possibility is when Rails is reading the > > multipart response in a largish upload (any upload request which > > can''t fit in socket buffers). > > On the three occasions I''ve had this problem it''s been a tiny request. > > The user clicks an ordinary Rails delete link. This POSTs to a URL > with two parameters: an authenticity token and the _method. > > The corresponding destroy action looks like: > > def destroy > client = Client.find params[:id] # 1 (ignores soft-deleted records) > client.soft_delete # 2 (sets a deleted_at timestamp) > client.brands.each(&:destroy) # 3 (a client has many brands) > redirect_to clients_path > end > > Nginx logged: > > x.xxx.xx.xx - - [27/Nov/2012:14:40:28 +0000] "POST /clients/2248 HTTP/1.1" 499 0 "https://example.com/clients/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" > x.xxx.xx.xx - - [27/Nov/2012:14:40:29 +0000] "POST /clients/2248 HTTP/1.1" 404 592 "https://example.com/companies/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" > > You can see the first request was terminated by the user. Hot on its > heels the user tried again and got a 404.Weird, and this is the only nginx instance that saw this request? Also, according to your logs above, the two requests above came from different Referer pages, so perhaps there were more requests involved that hit a different nginx?> The 404 was triggered by step 1 above: the first request had > successfully soft-deleted the client. However the client''s brands > were still in the database. The first request had executed steps 1 > and 2 but not step 3. > > Unicorn didn''t log anything. Rails didn''t log the first request but > did log the second.Odd. It''s been a long time since I looked at Rails; but doesn''t Rails log when a request _starts_? Also, doesn''t Rails log all DB queries? Or, by any chance, do you have query logging enabled in your DB to track this down?
On 30 Nov 2012, at 20:26, Eric Wong wrote:>> Nginx logged: >> >> x.xxx.xx.xx - - [27/Nov/2012:14:40:28 +0000] "POST /clients/2248 HTTP/1.1" 499 0 "https://example.com/clients/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" >> x.xxx.xx.xx - - [27/Nov/2012:14:40:29 +0000] "POST /clients/2248 HTTP/1.1" 404 592 "https://example.com/companies/2248/edit" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" >> >> You can see the first request was terminated by the user. Hot on its >> heels the user tried again and got a 404. > > Weird, and this is the only nginx instance that saw this request?That''s right, I only run a single nginx worker process.> Also, according to your logs above, the two requests above came from > different Referer pages, so perhaps there were more requests involved > that hit a different nginx?Bizarre as it sounds, that was a copy-paste mistake on my part. The second referrer should read: "https://example.com/clients/2248/edit".> Odd. It''s been a long time since I looked at Rails; but doesn''t Rails > log when a request _starts_? Also, doesn''t Rails log all DB queries?I think Rails logs when a request starts, then logs some more when the request ends ? but I''m not certain and I couldn''t find the answer when I looked in the Rails source. It must be there somewhere. Rails doesn''t log the DB queries in production, at least not by default.> Or, by any chance, do you have query logging enabled in your DB to track > this down?Regrettably not. It''s a weird problem which I''d like to dismiss, but it''s happened on two occasions now. I''m running an old version of Rails (3.0.12) which may or may not be relevant. Hmm.