Debugging On Rails

debugger commands, call controller from console, curl requests, useful browser tools.
Presented at kiev.rb#2 conference, Kiev, Ukraine 30 Nov 2013

Transcript

1. Debugging on Rails Mykhaylo Sorochan kiev.rb #2 kiev.rb #2
2. Contents
3. Sample app for the Ruby on Rails Tutorial (Rails 4) https://github.com/railstutorial/sample_app_rails_4 Debugged application
4. debugger gem 'debugger' debugger - call debugger config - .rdebugrc
5. Debug location UserController#show def show @user = User.find(params[:id]) debugger @microposts = @user.microposts.paginate(page: params[:page]) end
6. Debugger commands (rdb:9) help ruby-debug help v1.6.2 Type 'help <command-name>' for help on a specific command Available commands: backtrace delete enable help list pry restart source undisplay break disable eval info method ps save start up catch display exit irb next putl set step var condition down finish jump p quit show thread where continue edit frame kill pp reload skip trace
7. Program info (rdb:4) help info Generic command for showing things about the program being debugged. -- List of info subcommands: -- info args -- Argument variables of current stack frame info breakpoints -- Status of user-settable breakpoints info catch -- Exceptions that can be caught in the current stack frame info display -- Expressions to display when program stops info file -- Info about a particular file read in info files -- File names and timestamps of files read in info global_variables -- Global variables info instance_variables -- Instance variables of the current stack frame info line -- Line number and file name of current position in source file info locals -- Local variables of the current stack frame info program -- Execution status of the program info stack -- Backtrace of the stack info thread -- List info about thread NUM info threads -- information of currently-known threads info variables -- Local and instance variables of the current stack frame
8. Listing (rdb:1) help list l[ist] list forward l[ist] - list backward l[ist] = list current line l[ist] nn-mm list given lines NOTE - to turn on autolist, use 'set autolist' -> .rdebugrc
9. Listing: in debug 12 @user = User.find(params[:id]) 13 debugger => 14 @microposts = @user.microposts.paginate(page: params[:page]) 15 end 16
10. Listing: l 23,25 l 23,25 [23, 25] in */sample_app_rails_4/app/controllers/users_controller.rb 23 if @user.save 24 sign_in @user 25 flash[:success] = "Welcome to the Sample App!"
11. Breakpoints (rdb:4) help break b[reak] file:line [if expr] b[reak] class(.|#)method [if expr] set breakpoint to some position, (optionally) if expr == true (rdb:4) help delete del[ete][ nnn...] delete some or all breakpoints
12. Set breakpoint (rdb:4) b ApplicationHelper#full_title Breakpoint 1 at ApplicationHelper::full_title (rdb:4) b 18 Breakpoint 2 file */sample_app_rails_4/app/controllers/users_controller.rb, line 18 (rdb:4) info b Num Enb What 1 y at ApplicationHelper:full_title 2 y at */sample_app_rails_4/app/controllers/users_controller.rb:18
13. Navigate (rdb:4) help step s[tep][+-]?[ nnn] step (into methods) once or nnn times '+' forces to move to another line. '-' is the opposite of '+' and disables the force_stepping setting. (rdb:4) help next n[ext][+-]?[ nnn] step over once or nnn times, '+' forces to move to another line. '-' is the opposite of '+' and disables the force_stepping setting. (rdb:4) help up up[count] move to higher frame
14. Stop at breakpoint (rdb:4) c Breakpoint 1 at ApplicationHelper:full_title [-1, 8] in */sample_app_rails_4/app/helpers/application_helper.rb 1 module ApplicationHelper 2 3 # Returns the full title on a per-page basis. => 4 def full_title(page_title) 5 base_title = "Ruby on Rails Tutorial Sample App"
15. Display (rdb:4) help display disp[lay] <expression> add expression into display expression list disp[lay] display expression list (rdb:4) help undisplay undisp[lay][ nnn] Cancel some expressions to be displayed when program stops.
16. Display configured 4 def full_title(page_title) => 5 base_title = "Ruby on Rails Tutorial Sample App" 6 if page_title.empty? (rdb:4) disp 2: controller_name = users 3: base_title =
17. Display changed (rdb:4) n */sample_app_rails_4/app/helpers/application_helper.rb:6 if page_title.empty? 2: controller_name = users 3: base_title = Ruby on Rails Tutorial Sample App [1, 10] in */sample_app_rails_4/app/helpers/application_helper.rb 5 base_title = "Ruby on Rails Tutorial Sample App" => 6 if page_title.empty? 7 base_title
18. Conditional breakpoint (rdb:8) b ApplicationHelper#full_title if page_title=="Alexander" Breakpoint 4 at ApplicationHelper::full_title (rdb:8) c Breakpoint 1 at ApplicationHelper:full_title
19. Variables (rdb:8) help var v[ar] cl[ass] show class variables of self v[ar] co[nst] <object> show constants of object v[ar] g[lobal] show global variables v[ar] i[nstance] <object> show instance variables of object. You may pass object id's hex as well. v[ar] l[ocal] show local variables
20. Show variables 12 @user = User.find(params[:id]) 13 debugger => 14 @microposts = @user.microposts.paginate(page: params[:page]) 15 end 16 17 def new (rdb:12) v i @_action_has_layout = true @_action_name = "show" @_config = {} @_env = {"GATEWAY_INTERFACE"=>"CGI/1.1", "PATH_INFO"=>"/users/1", "QUERY_STRING"=>"",... @_headers = {"Content-Type"=>"text/html"} @_lookup_context = #<ActionView::LookupContext:0x00000008e4b710 @details_key=nil, @details={:loc... @_params = {"action"=>"show", "controller"=>"users", "id"=>"1"} @_prefixes = ["users", "application"] @_request = #<ActionDispatch::Request:0x00000008e4bad0 @env={"GATEWAY_INTERFACE"=>"CGI/1.... @_response = #<ActionDispatch::Response:0x00000008e4baa8 @mon_owner=nil, @mon_count=0, @mo... @_response_body = nil @_routes = nil @_status = 200 @user = #<User id: 1, name: "Alexander", email: "asdf@asdf.com", created_at: "2013-11...
21. Remote debugger Client # rdebug --client -h 127.0.0.1 Connected. */sample_app_rails_4/app/controllers/users_controller.rb:14 @microposts = @user.microposts.paginate(page: params[:page]) [9, 18] in */sample_app_rails_4/app/controllers/users_controller.rb 9 end 10 11 def show 12 @user = User.find(params[:id]) 13 debugger => 14 @microposts = @user.microposts.paginate(page: params[:page]) Server Debugger.wait_connection = true Debugger.start_remote
22. pry REPL
23. debugger-pry Call pry from debugger
24. pry-debugger Debugger commands inside pry: step, next, continue, breakpoints
25. jazz_hands jazz_hands is an opinionated set of console- related gems and a bit of glue: pry, awesome_print, hirb, pry-rails, pry-doc, pry-git, pry-remote, pry-debugger, pry-stack_explorer, coolline, coderay
26. pry – jazz_hands 1
27. pry – jazz_hands 2
28. pry – jazz_hands 3
29. pry – jazz_hands 4
30. Logging ActiveSupport::Logger is used for logging Rails.root/log/[environment_name].log
31. Log levels Rails.logger.level | name | level | |----------+-------| | :debug | 0 | | :info | 1 | | :warn | 2 | | :error | 3 | | :fatal | 4 | | :unknown | 5 | development, testing: log_level = 0 (:debug) production: log_level = 1 Messages with equal or higher level are sent to log
32. Write to log logger.debug User.inspect logger.info user.id logger.fatal "Help!"
33. Tagging log messages logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)) logger.tagged("USER") { logger.info "hello" } => [USER] hello
34. Tagged logging def show @user = User.find(params[:id]) logger.tagged("USER") { logger.info @user.email } # tail -f log/development.log|grep \\\[USER\] [USER] asdf@asdf.com
35. Global variables for tracing __FILE__ - file name __LINE__ - line number
36. Some useful CLI commands tail -n 100 tail -f grep, less
37. Querying logs # cat log/development.log|grep GET|tail -n 2 Started GET "/assets/users.js?body=1" for 127.0.0.1 at 2013-11-21 23:32:01 +0200 Started GET "/assets/application.js?body=1" for 127.0.0.1 at 2013-11-21 23:32:01 +0200 # cat log/development.log|grep GET|wc -l 574
38. config.log_formatter Defines the formatter of the Rails logger. Defaults to ActiveSupport::Logger::SimpleFormatter for all modes, production defaults to Logger::Formatter. module ActiveSupport class Logger < ::Logger # Simple formatter which only displays the message. class SimpleFormatter < ::Logger::Formatter # This method is invoked when a log event occurs def call(severity, timestamp, progname, msg) "#{String === msg ? msg : msg.inspect}\n" end end
39. config.log_level Defaults to :debug for all modes, production defaults to :info.
40. config.log_tags See ActionDispatch::Request methods. config.log_tags = [ :fullpath ] [/users/1] Started GET "/users/1" for 127.0.0.1 at 2013-11-... [/users/1] ActiveRecord::SchemaMigration Load (0.1ms) SELECT ... [/assets/application.css?body=1] Started GET "/assets/application.css?body=1" for 127...
41. config.logger Accepts a logger conforming to the interface of Log4r or the default Ruby Logger class. Defaults to ActiveSupport::Logger, with auto flushing off in production mode.
42. Rails console rails c rails c --sandbox irb pry
43. rake routes > all_routes = Rails.application.routes.routes > require 'action_dispatch/routing/inspector' > inspector = ActionDispatch::Routing::RoutesInspector.new(all_routes)
44. All routes > puts inspector.format(ActionDispatch::Routing::ConsoleFormatter.new) Prefix Verb URI Pattern Controller#Action following_user GET /users/:id/following(.:format) users#following followers_user GET /users/:id/followers(.:format) users#followers users GET /users(.:format) users#index POST /users(.:format) users#create new_user GET /users/new(.:format) users#new edit_user GET /users/:id/edit(.:format) users#edit user GET /users/:id(.:format) users#show PATCH /users/:id(.:format) users#update PUT /users/:id(.:format) users#update DELETE /users/:id(.:format) users#destroy sessions POST /sessions(.:format) sessions#create new_session GET /sessions/new(.:format) sessions#new session DELETE /sessions/:id(.:format) sessions#destroy microposts POST /microposts(.:format) microposts#create micropost DELETE /microposts/:id(.:format) microposts#destroy relationships POST /relationships(.:format) relationships#create relationship DELETE /relationships/:id(.:format) relationships#destroy root GET / static_pages#home signup GET /signup(.:format) users#new
45. Routes for controller > puts inspector.format(ActionDispatch::Routing::ConsoleFormatter.new, 'microposts') Prefix Verb URI Pattern Controller#Action microposts POST /microposts(.:format) microposts#create micropost DELETE /microposts/:id(.:format) microposts#destroy
46. Filtering routes: GET > puts inspector.format(ActionDispatch::Routing::ConsoleFormatter.new, 'users').lines.grep(/GET/).join following_user GET /users/:id/following(.:format) users#following followers_user GET /users/:id/followers(.:format) users#followers users GET /users(.:format) users#index new_user GET /users/new(.:format) users#new edit_user GET /users/:id/edit(.:format) users#edit user GET /users/:id(.:format) users#show signup GET /signup(.:format) users#new
47. Filtering routes: /relation/ > puts inspector.format(ActionDispatch::Routing::ConsoleFormatter.new).lines.grep(/relation/).join relationships POST /relationships(.:format) relationships#create relationship DELETE /relationships/:id(.:format) relationships#destroy
48. Matching routes > r = Rails.application.routes > r.recognize_path "/users/47" => {:action=>"show", :controller=>"users", :id=>"47"} > r.recognize_path "/users/87", :method => "PUT" => {:action=>"update", :controller=>"users", :id=>"87"} > r.recognize_path "/users/47.json" => {:action=>"show", :controller=>"users", :id=>"47", :format=>"json"}
49. Named routes > app.users_path => "/users" > app.users_path(:json) => "/users.json" > app.user_path(1) => "/users/1" > app.user_path(1, :xml) => "/users/1.xml" > app.user_path(1, :count => 4) => "/users/1?count=4"
50. Making requests > app => #<ActionDispatch::Integration::Session:...> > app.reset!
51. Get requests > app.get '/users/1/edit' Started GET "/users/1/edit" for 127.0.0.1 at 2013-11-26 23:24:18 +0200 Processing by UsersController#edit as HTML Parameters: {"id"=>"1"} Redirected to http://localhost:3000/signin Filter chain halted as :signed_in_user rendered or redirected Completed 302 Found in 3ms (ActiveRecord: 0.4ms) > app.response.body => "<html><body>You are being <a href=\"http://localhost:3000/signin\">redirected</a>.</body></html>" > app.get_via_redirect '/users/1/edit' Started GET "/users/1/edit" for 127.0.0.1 at 2013-11-26 23:26:44 +0200 Redirected to http://localhost:3000/signin ... Started GET "/signin" for 127.0.0.1 at 2013-11-26 23:26:44 +0200
52. Session cookies > app.cookies => #<Rack::Test::CookieJar... > app.cookies.to_hash => {"_sample_app_session"=>"RC9j... app.cookies - received/sent cookies
53. Post requests: signin > app.response.body.lines.grep /csrf-token/ => ["<meta content=\"n+9uCcG2JJmgwhnNcp4s9jTwOU55RAPOdtAHWstcpKQ=\" name=\"csrf-token\" />\n"] > app.post '/sessions', :authenticity_token => 'n+9uCcG2JJmgwhnNcp4s9jTwOU55RAPOdtAHWstcpKQ=', 'session[email]' => 'asdf@asdf.com', 'session[password]' => '123456' Started POST "/sessions" for 127.0.0.1 at 2013-11-26 23:33:01 +0200 Processing by SessionsController#create as HTML Parameters: {"authenticity_token"=>"n+9uCcG2JJmgwhnNcp4s9jTwOU55RAPOdtAHWstcpKQ=", "session"=>{"email" =>"asdf@asdf.com", "password"=>"[FILTERED]"}} Redirected to http://localhost:3000/users/1/edit Completed 302 Found in 281ms (ActiveRecord: 7.2ms) app.post_via_redirect
54. Access to restricted resource > app.get '/users/1/edit' Started GET "/users/1/edit" for 127.0.0.1 at 2013-11-26 23:38:47 +0200 Processing by UsersController#edit as HTML Completed 200 OK in 41ms (Views: 35.7ms | ActiveRecord: 0.8ms)
55. Call helper > helper => #<ActionView::Base:... > # ApplicationHelper#full_title > helper.full_title "Sign Up" => "Ruby on Rails Tutorial Sample App | Sign Up"
56. Call helper with cookie > def cookies; @cookies ||= HashWithIndifferentAccess.new(app.cookies.to_hash); end > helper.current_user => #<User id: 1, name: ....
57. ActiveRecord logging > ActiveRecord::Base.logger = Logger.new(STDOUT) > ActiveRecord::Base.clear_active_connections! > # reload! > User.find 1 D, [2013-12-30T21:55:17.775769 #24810] DEBUG -- : User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT 1 [["id", 1]] => #<User id: 1, name: "hello",....
58. ActiveRecord hide logging > ActiveRecord::Base.logger = Logger.new(nil) > ActiveRecord::Base.clear_active_connections! > # reload! > User.find 1 => #<User id: 1, name: "hello",....
59. Raw SQL requests > ActiveRecord::Base.connection.select_all("select * from users") => #<ActiveRecord::Result:... > puts _ {"id"=>1, "name"=>"hello", "email"=>"hello@hello.com", "created_at"=>"2013-....
60. .irbrc Save your helper methods • routes • sql logging • etc
61. CLI tools Making HTTP requests with curl • -s silent • -v verbose • -c save cookie • -b use cookie • -data POST data • -data-urlencode URL-encode POST data
62. Access restricted area curl -s -v http://localhost:3000/users/1/edit > /dev/null > GET /users/1/edit HTTP/1.1 < HTTP/1.1 302 Found < Location: http://localhost:3000/signin
63. Visit /signin, get token curl -s -c hello_cookies http://localhost:3000/signin > /dev/null |grep csrf-token <meta content="/t/IoUQxKVEL+KR2/HsnxTKmnALUA99jIr/LvjlgPKs=" name="csrf-token" />
64. Sign in curl -s -v --data "session[email]=asdf@asdf.com;session[password]=123456" \ --data-urlencode "authenticity_token=/t/IoUQxKVEL+KR2/HsnxTKmnALUA99jIr/LvjlgPKs=" \ -b hello_cookies -c cookies \ http://localhost:3000/sessions > /dev/null > POST /sessions HTTP/1.1 < HTTP/1.1 302 Found < Location: http://localhost:3000/users/1
65. Successful access to restricted area curl -s -v http://localhost:3000/users/1/edit -b cookies > /dev/null > GET /users/1/edit HTTP/1.1 < HTTP/1.1 200 OK
66. Browser tools • console • render helpers • debug info • etc
67. rack-webconsole >> User.find 1 => #<User id: 1, name: "Alexander", email: "asdf@asdf.com", created_at: "2013-11-17 16:19:07", updated_at: "2013-11-27 21:52:06", password_digest: "$2a$10$MEICr2zekeBhh9HYCMLmXut3ckOsiL0TkksFWVX4asFf...", remember_token: "cda4da34a5ee4238ddb78f20d4ec7e52b59fab4e", admin: nil> >> helper => Error: undefined local variable or method `helper' for #<Rack::Webconsole::Sandbox:0x000000089cf600> >> app => Error: undefined local variable or method `app' for #<Rack::Webconsole::Sandbox:0x000000089cf600> >> Rails.root => #<Pathname:*/sample_app_rails_4> >> self => #<Rack::Webconsole::Sandbox:0x000000089cf600 @locals={:u=>#<User id: 1, name: "Alexander"
68. rack-webconsole ` - activate
69. Rails Panel
70. rails-footnotes: Assigns
71. rails-footnotes: DB
72. rails-footnotes: disable ?footnotes=false
73. xray-rails Ctrl+Shift+X
74. better_errors 1
75. better_errors 2
76. exception_notifier Provides a set of notifiers for sending notifications when errors occur in a Rack/Rails application
77. letter_opener Preview email in the browser instead of sending it
78. exception_notifier + letter_opener
79. Chrome: Form Editor
80. Chrome: JunkFill
81. Chrome: Sight
82. API calls, sight
83. hurl.it: params
84. hurl.it: response
85. POSTMAN
86. Chrome: REST console
87. Chrome: Advanced Rest Client
88. ВСЁ