Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Logging on hijack requests is weird #332

Closed
SamSaffron opened this issue Jul 18, 2013 · 9 comments
Closed

Logging on hijack requests is weird #332

SamSaffron opened this issue Jul 18, 2013 · 9 comments

Comments

@SamSaffron
Copy link

Take the following config.ru

def respond(io)  
  data = "<html><body>hello world</html></body>"
  io.write("HTTP/1.1 200 OK\r\n")
  io.write("Content-Type: text/html; charset=UTF-8\r\n")
  io.write("Cache-Control: must-revalidate, private, max-age=0\r\n")
  io.write("Content-Length: #{data.bytes.length}\r\n")
  io.write("Connection: close\r\n")
  io.write("\r\n")
  io.write(data)
  io.close
end

run lambda { |env|  
  io = env['rack.hijack'].call

  Thread.new do
    sleep 2
    respond(io)
  end

  [418,{},["I'm a teapot"]]
}

after getting a request we see:

10.0.0.55 - - [18/Jul/2013 21:21:30] "GET / HTTP/1.0" 418 - 0.0001

The response code is actually 200, the 418 is to be ignored by the web server so no point showing it... instead the log should read

10.0.0.55 - - [18/Jul/2013 21:21:30] "GET / HTTP/1.0" HIJACK - 0.0001

In an ideal world you would hold of on the log till .close is called on the io, and log the time of hijack and time of close.

Also, in other news performance is spectacular with hijack on with a tuned linux

sam@ubuntu:~/Source/weighttp$ ab -n 5000 -c 5000 http://l.discourse:9292/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking l.discourse (be patient)
Completed 500 requests
Completed 1000 requests
Completed 1500 requests
Completed 2000 requests
Completed 2500 requests
Completed 3000 requests
Completed 3500 requests
Completed 4000 requests
Completed 4500 requests
Completed 5000 requests
Finished 5000 requests


Server Software:        
Server Hostname:        l.discourse
Server Port:            9292

Document Path:          /
Document Length:        37 bytes

Concurrency Level:      5000
Time taken for tests:   6.825 seconds
Complete requests:      5000
Failed requests:        0
Write errors:           0
Total transferred:      935000 bytes
HTML transferred:       185000 bytes
Requests per second:    732.62 [#/sec] (mean)
Time per request:       6824.778 [ms] (mean)
Time per request:       1.365 [ms] (mean, across all concurrent requests)
Transfer rate:          133.79 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0 1022 1212.9    998    3017
Processing:  2002 2330 179.1   2328    4416
Waiting:     2002 2275 172.8   2271    4416
Total:       2032 3352 1297.6   3030    5903

Percentage of the requests served within a certain time (ms)
  50%   3030
  66%   3213
  75%   3292
  80%   5405
  90%   5510
  95%   5548
  98%   5886
  99%   5897
 100%   5903 (longest request)

That is right ... 5000 concurrent sleeping 2 secs, all serviced with 6 secs ... not too bad.

However, if you try this on a vanilla linux, stuff can get pretty weird, recommend you test out that ab command on a system that runs out of resources during the ab test, stuff got weird.
@evanphx
Copy link
Member

evanphx commented Jul 18, 2013

Yeah, logging on hijack is super weird. The issue is that the middleware stack is what actually does the logging so there isn't an easy way for puma to inject itself genericly. I'm going to make a change to the Rack::CommonLogger patch we use to detect hijacking and do something better, but that won't work in all cases because a different logger might be in the middleware stack.

@SamSaffron
Copy link
Author

thanks, yeah the hijack protocol is weird, personally I think using Thin style throw :async after hijacking feels cleaner cause all sorts of weird can happen unwinding a big middleware stack. (etags, caching and so on)

@wedgemartin
Copy link

I'm running puma 2.6.0, and since the patch, the response code is always 'HIJACKED'. I've been unable to figure out a way to change it to anything from that without hacking the gem itself, which I'd like to avoid. The problem is that when I run puma in production mode, it always reports a 500 from this call, even though it succeeds. When run in development mode, it shows that the response code is actually HIJACKED, but I don't want to get into issues with NewRelic reporting high error rates just because it thinks the response code is bad ( though I've not tested this with NewRelic yet, but I assume it will be the case )

@wedgemartin
Copy link

:Looking at your patch it looks like this may only effect the log entry... hopefully.

@wedgemartin
Copy link

The problem could also be that I'm a jackass. I was looking at the production.log file when running in development mode... Had I been looking at the dev log, I would've seen the actual error, which has nothing to do with this. Interesting though, that puma seems to ignore the RAILS_ENV and write to the production.log for the hijack output regardless. Likely because the environment of my lambda'd process does not have RAILS_ENV set and it's defaulting to production or something along those lines.

@evanphx
Copy link
Member

evanphx commented Oct 21, 2013

Puma don't write to any log files without being told to, so thats not it writing to production.log.

@supagroova
Copy link

@SamSaffron we've recently authored a gem that provided this kind of async processing in Grape API (supporting the Rack Hijack API or AsyncCallback were applicable) called StuartApp/grape-async. We're about to jump into doing perf testing and I was wondering if you could provide some more details on the changes you made to your linux setup to achieve the performance you mentioned above?

@SamSaffron
Copy link
Author

honestly I don't remember off the top of my head, raise ulimits is the main one

@supagroova
Copy link

Ok thanks, we’ll share any further tweaks we find that work well here in the future.

On 03 Feb 2016, at 09:15, Sam notifications@github.com wrote:

honestly I don't remember off the top of my head, raise ulimits is the main one

—
Reply to this email directly or view it on GitHub #332 (comment).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@evanphx @SamSaffron @supagroova @wedgemartin