Debugging Production Service Oriented Systems

Presented at Cascadia Ruby Conference in Seattle.

Transcript

3. 4:40am
9. Bug? Where is it?
10. System Down? Which one?
11. Database Problems? What’s the Cause?
13. Andy Delcambre @adelcambre
17. It could be better!
18. Track Requests SystemWide
19. Step 1 Generate Request Id
20. Rack middleware
21. class RequestId::Middleware def initialize(app) @app = app end def call(e) Thread.current["req_id"] = e["HTTP_X_REQ_ID"] || UUID.generate @app.call(e).tap do |stat, head, body| headers["X-Req-Id"] = Thread.current["req_id"] end end end
22. class RequestId::Middleware def initialize(app) @app = app end def call(e) Thread.current["req_id"] = e["HTTP_X_REQ_ID"] || UUID.generate @app.call(e).tap do |stat, head, body| headers["X-Req-Id"] = Thread.current["req_id"] end end end
23. class RequestId::Middleware def initialize(app) @app = app end def call(e) Thread.current["req_id"] = e["HTTP_X_REQ_ID"] || UUID.generate @app.call(e).tap do |stat, head, body| headers["X-Req-Id"] = Thread.current["req_id"] end end end
24. class RequestId::Middleware def initialize(app) @app = app end def call(e) Thread.current["req_id"] = e["HTTP_X_REQ_ID"] || UUID.generate @app.call(e).tap do |stat, head, body| headers["X-Req-Id"] = Thread.current["req_id"] end end end
25. Initiator Frontend Background Worker Backend 2 Backend 1 Set an id for every request
26. Log All The Requests!
27. class RequestIdLogger def call(e) begin start = Time.now @app.call(e) ensure req_id = Thread.current["req_id"] client.post( "/requests", {}, env.merge(:req_id => req_id :start => start, :end => Time.now).to_json) end end end
28. class RequestIdLogger def call(e) begin start = Time.now @app.call(e) ensure req_id = Thread.current["req_id"] client.post( "/requests", {}, env.merge(:req_id => req_id :start => start, :end => Time.now).to_json) end end end
29. class RequestIdLogger def call(e) begin start = Time.now @app.call(e) ensure req_id = Thread.current["req_id"] client.post( "/requests", {}, env.merge(:req_id => req_id :start => start, :end => Time.now).to_json) end end end
30. class RequestIdLogger def call(e) begin start = Time.now @app.call(e) ensure req_id = Thread.current["req_id"] client.post( "/requests", {}, env.merge(:req_id => req_id :start => start, :end => Time.now).to_json) end end end
31. class RequestIdLogger def call(e) begin start = Time.now @app.call(e) ensure req_id = Thread.current["req_id"] client.post( "/requests", {}, env.merge(:req_id => req_id :start => start, :end => Time.now).to_json) end end end
32. Log exceptions With request id
33. class ExceptionLogger def call(env) begin @app.call(env) rescue => e req_id = Thread.current["req_id"] client.post("/errors", {}, {:request => env.to_hash, :exception => e.to_hash, :ruby_env => ENV.to_hash, :request_id => req_id }.to_json) raise end end end
34. class ExceptionLogger def call(env) begin @app.call(env) rescue => e req_id = Thread.current["req_id"] client.post("/errors", {}, {:request => env.to_hash, :exception => e.to_hash, :ruby_env => ENV.to_hash, :request_id => req_id }.to_json) raise end end end
35. Benefits?
36. Step 2 Resque
37. module RequestID def enqueue(*args) req_id = Thread.current["req_id"] Resque.enqueue(self, req_id, *args) end end
38. module RequestID def enqueue(*args) req_id = Thread.current["req_id"] Resque.enqueue(self, req_id, *args) end end
39. module RequestID def enqueue(*args) req_id = Thread.current["req_id"] Resque.enqueue(self, req_id, *args) end end
40. module RequestID def around_perform_req_id(req_id, *args) begin start = Time.now yield ensure client.post("/requests", {}, {:req_id => req_id :start => start, :end => Time.now, :args => args, :type => "job"}.to_json) end end end
41. module RequestID def around_perform_req_id(req_id, *args) begin start = Time.now yield ensure client.post("/requests", {}, {:req_id => req_id :start => start, :end => Time.now, :args => args, :type => "job"}.to_json) end end end
42. module RequestID def around_perform_req_id(req_id, *args) begin start = Time.now yield ensure client.post("/requests", {}, {:req_id => req_id :start => start, :end => Time.now, :args => args, :type => "job"}.to_json) end end end
43. module RequestID def around_perform_req_id(req_id, *args) begin start = Time.now yield ensure client.post("/requests", {}, {:req_id => req_id :start => start, :end => Time.now, :args => args, :type => "job"}.to_json) end end end
44. class MyJob extend RequestID def self.queue; :default; end def self.perform(req_id, job_arg) # Do work end end MyJob.enqueue("arg")
45. class MyJob extend RequestID def self.queue; :default; end def self.perform(req_id, job_arg) # Do work end end MyJob.enqueue("arg")
46. class MyJob extend RequestID def self.queue; :default; end def self.perform(req_id, job_arg) # Do work end end MyJob.enqueue("arg")
47. class MyJob extend RequestID def self.queue; :default; end def self.perform(req_id, job_arg) # Do work end end MyJob.enqueue("arg")
48. Initiator Frontend Background Worker Backend 2 Backend 1 Pass the Id to Workers
49. Log reqsue exceptions With request id
50. module RequestID def around_perform_track(req_id, *args) begin yield rescue => e req_id = Thread.current["req_id"] client.post("/errors", {}, {:args => args, :exception => e.to_hash, :ruby_env => ENV.to_hash, :request_id => req_id, :type => "job" }.to_json) end end end
51. module RequestID def around_perform_track(req_id, *args) begin yield rescue => e req_id = Thread.current["req_id"] client.post("/errors", {}, {:args => args, :exception => e.to_hash, :ruby_env => ENV.to_hash, :request_id => req_id, :type => "job" }.to_json) end end end
52. module RequestID def around_perform_track(req_id, *args) begin yield rescue => e req_id = Thread.current["req_id"] client.post("/errors", {}, {:args => args, :exception => e.to_hash, :ruby_env => ENV.to_hash, :request_id => req_id, :type => "job" }.to_json) end end end
53. Now it gets interesting!
54. Correlate Errors
55. Tie job to the Request
56. Step 3 Backends
57. rack client -
58. class ClientMiddleware def initialize(app) @app = app end def call(env) req_id = Thread.current["req_id"] @app.call( env.merge( "HTTP_X_REQ_ID" => req_id)) end end Rack::Client::Simple.use ClientMiddleware
59. class ClientMiddleware def initialize(app) @app = app end def call(env) req_id = Thread.current["req_id"] @app.call( env.merge( "HTTP_X_REQ_ID" => req_id)) end end Rack::Client::Simple.use ClientMiddleware
60. class ClientMiddleware def initialize(app) @app = app end def call(env) req_id = Thread.current["req_id"] @app.call( env.merge( "HTTP_X_REQ_ID" => req_id)) end end Rack::Client::Simple.use ClientMiddleware
61. class ClientMiddleware def initialize(app) @app = app end def call(env) req_id = Thread.current["req_id"] @app.call( env.merge( "HTTP_X_REQ_ID" => req_id)) end end Rack::Client::Simple.use ClientMiddleware
62. class ClientMiddleware def initialize(app) @app = app end def call(env) req_id = Thread.current["req_id"] @app.call( env.merge( "HTTP_X_REQ_ID" => req_id)) end end Rack::Client::Simple.use ClientMiddleware
63. class RequestId::Middleware def initialize(app) @app = app end def call(e) Thread.current["req_id"] = e["HTTP_X_REQ_ID"] || UUID.generate @app.call(e).tap do |stat, head, body| headers["X-Req-Id"] = Thread.current["req_id"] end end end
64. Initiator Frontend Background Worker Backend 2 Backend 1 Pass the id to Backends
65. So now what?
66. More Correlation
67. Request Logging What else Can we Do?
68. Request Traces See the full Stack
69. Roll em up Changes over Time
70. You want to put it where!?
71. Mysql? Could work
72. Mongo? Built for Analytics
73. Elastic Search You Know, For Search
74. Painless Setup
75. Distributed
76. JSON/HTTP API
77. $ curl -XPUT http://localhost:9200/twitter/tweet/2 -d '{ "user": "kimchy", "post_date": "2009-11-15T14:12:12", "message": "You know, for Search" }' $ curl -XGET http://localhost:9200/twitter/tweet/_search? q=user:kimchy
78. $ curl -XGET http://localhost:9200/twitter/_search -d '{ "query" : { "range" : { "post_date" : { "from" : "2009-11-15T13:00:00", "to" : "2009-11-15T14:30:00" } } } }'
79. Dapper
80. Google Dapper http://bit.ly/googledapper
81. Thread Locals
82. Deferred Calls
83. RPC Framework
85. What’s different?
86. WIP
87. Thanks! @adelcambre