p self #=> ޒेཛྷ໌/igaiga Ruby and Rails freelancer in Tokyo I've wrote some Ruby books in Japan Love Ruby, Love Taiwan, Love 50ཛྷ https://twitter.com/igaiga555
•"How to talk with objects" •Ruby basics for debugging •Case study "Stolen instance variable" •How to trace instance variable assignments •Keyword: TracePoint, RubyVM::AbstractSyntaxTree •Other topics •Introduce some great techniques for debugging • Keyword: Tracer, ObjectSpace#allocation_sourcefile, g, signal Road to white mages Contents
What's magics in Ruby? matz "There are 2 magics. White magics do good things, Black magics do evil things." In my opinion "Magics will make something that looks impossible possible" In "Metaprogramming Ruby" book • What's magics? • Techniques in metaprogramming • What's metaprogramming? • Writing codes to generate codes • Writing codes to manipulate codes in running
Why are they GREAT black mages? They can protect party members Black magics sometimes would go out of control. Black magics affects incredible ways. Great black mages have skill to control the power too. We must use black magics in safety. But that's difficult to control precisely. Rules in black magics - †Ruby Black Magics Scriptures† by joker1007 • Don't destroy built in libraries • Keep stack traces traceable • To take performance into account • Writing TracePoint codes explicit
White magics and Black magics "White magics" are debugging magics We can try easier in non production code. For example, debugging codes. So, let's start to use magics for debugging! Black magics: Magics to get values White magics: Magics to cure codes "White magics" (in this talk) : magical techniques for debugging
•"How to talk with objects" •Ruby basics for debugging •Case study "Stolen instance variable" •How to trace instance variable assignments •Keyword: TracePoint, RubyVM::AbstractSyntaxTree •Other topics •Introduce some great techniques for debugging • Keyword: Tracer, ObjectSpace#allocation_sourcefile, g, signal Road to white mages Contents
How to use debugger We can suspend programs • binding.irb (Built-in library) • pry gem series • binding.pry • pry-byebug gem • to run step by step • pry-doc gem • to show method define codes • pry on $ prying=true rspec spec/file_spec.rb • pry off $ rspec spec/file_spec.rb we can also use conditions to suspend
What kind/number of objects are there? ObjectSpace: There are all living objects in an Ruby world • ObjectSpace (Built-in class) • Module to treat Ruby objects world • "allow you to traverse all living objects with an iterator" • ObjectSpace.each_object(klass) • gets objects filtered with classes or subclasses by argument. • Getting all Class objects: ObjectSpace.each_object(Class) • ObjectSpace.count_objects • Counts all objects grouped by type
What methods do you have? Show methods that we can call •Kernel#methods method • get callable methods with the objects • [1,2,3].methods #=> instance methods • Array.methods #=> class methods
Where are you from? Defined informations getting with Method objects • Method objects are got by Object#method, Module#instance_method • Method object has these methods • source_location: defined source file • owner: defined in class • parameters: informations of arguments method(:pp).source_location #=> ["/Users/igaiga/.rbenv/versions/2.6.2/lib/ruby/2.6.0/pp.rb", 582] method(:pp).owner #=> Kernel require "time" Time.instance_method(:httpdate).source_location #=> ["/Users/igaiga/.rbenv/versions/2.6.2/lib/ruby/2.6.0/time.rb", 691] Time.instance_method(:succ).source_location #=> nil # Native method (Not written in Ruby) returns nil
Where are you from? Show paths where is the gem placed • gem which [gem name] • bundle show [gem name] • bundle open [gem name] • open in specified editor • To specify environment variable in EDITOR or BUNDLER_EDITOR
Where are you from Show methods called history • Kernel#caller • tell us methods called history • Kernel#caller_locations • same as caller, but get Thread::Backtrace::Location objects • Exception#backtrace • get methods called history that collects in the exception raised. Useful in rescue.
Source code's world, Object's world Debugging is difficult because we have 2 worlds • In drama metaphor • Source code is an acting script • Only we can do is writing these scripts • Object's world is a stage • A world running programs • We can't act in there, and we can't watch them. Object's world ➡ Source code's world ➡ p 1+2 1 + 2 Integer objects
White magic introduction In conclusion • We can get many informations to talk with objects • We can also change objects in almost cases • There is a distance in "Source code's world" and "Object's world" We will use some of them later
Case study "Stolen instance variable" How to detect assignment of instance variables? • Find "How to trace assignment of instance variables" • For grobal variable: Kernel#trace_var • But there are no method for instance variables • Instance variables are not objects. • So we can't talk with them. • Codes in the slides : https://github.com/igaiga/RubyConfTaiwan2019 Case: In a Rails app, displaying book data with instance variable @books, but the shown data are incorrect. Correct Current @books #=> []
"How to trace assignment to instance variables" Setup First target code is following one in minimum. Goal: trace assignment to @hi ※ In this story, we don't use grep.
TracePoint (TP) Set block called with some events Make TracePoint with block, specified events call the block. https://ruby-doc.org /core-2.6.3/TracePoint.html Events • :line execute code on a new line • :call call a Ruby method • :c_call call a C-language routine • :b_call event hook at block entry • :raise raise an exception ⬅ log in TracePoint block ⬅ log in TracePoint block ⬇ Set TracePoint block ⬅ :line event trigger ↖ :line event trigger :line event ⬇
TracePoint (TP) Get informations by TP object in block variable TracePoint.trace(:line) ➡ TP block called with all execute code There're useful informations by block variable |tp| (We can find methods by tp.methods.) • event kind of event • path source path • lineno source line number • method_id method name • defined_class class name [TP:line] tp.rb:3 hi User ⬆ Informations from tp ⬇ Set TracePoint block ⬅ :line event ⬅ :line event
TracePoint (TP) Find "instance variable assignment codes" in all execute codes Our TP block code is called with all execute codes. But we only need "instance variable assignment codes". How to get the meaning of code? How to find instance variable assignment codes? ⬅ log in TracePoint block ⬅ log in TracePoint block ⬅ :line event ⬅ :line event By TP object, we can get some informations, but we can't get the triggered code.
TracePoint (TP) Get the source code We couldn't get triggered code by TP object, but we know triggered code's path and line number. ➡ OK. Open the source code file! " @hi = \"hi(ŇŋωŋŇ)ϊ\"\n" We've got the code! Yeah! Next, we want to know what the code mean. ⬆ Open triggered code file using with TP object informations
RubyVM::AbstractSyntaxTree (AST) Introduce AST to get code means Using RubyVM::AbstractSyntaxTree.parse, we can get what's the meaning of the code. What's the AST? RubyVM::AbstractSyntaxTree.parse(" @hi = \"hi(ŇŋωŋŇ)ϊ\"\n") #
RubyVM::AbstractSyntaxTree What's the AbstractSyntaxTree(AST) ? Flow of Ruby codes execution Referenced by siman's slide (ja) https://speakerdeck.com/siman/railsdm2019?slide=6 RubyVM::AbstractSyntaxTree.parse object world code world Ruby Under a Microscope http://patshaughnessy.net/ruby-under-a-microscope 3VCZ DPEF 5PLFOT "45 *4FR
TracePoint & AST How to detect instance variable specified name ⬅⬇ Check instance variable name ⬅ @hi ⬅ Make argument specified variable name Current: Detecting specified instance variable assignment Next: Detecting assignment in specified class
tp.self : Object that triggered the event tp.self.is_a?(klass) : Check the object is a klass class's object TracePoint & AST How to detect instance variable in specified class ⬅ class name "User" ⬅ "User" to User ⬅ Check class of triggered object ⬅ Make argument specified class
Build a Rails app Book (title, memo) CRUD • $ rails new books_app • $ cd books_app • $ rails g scaffold book title:string memo:text • $ rails db:migrate • place detecting codes in config/initializers ➡ Specify instance variable name. ⬆ (It doesn't specify class name to detect in all classes.) https://github.com/igaiga/RubyConfTaiwan2019/blob/master/ missing_instance_variables_sample_rails_app/config/initializers/ trace_instance_variables.rb ⬅ tracer("@books")
Started GET "/books" for ::1 at 2019-06-08 12:34:50 +0900 Processing by BooksController#index as HTML @books is assigned in /path_to_app/app/controllers/books_controller.rb:7 index BooksController Rendering books/index.html.erb within layouts/application Book Load (6.8ms) SELECT "books".* FROM "books" ↳ app/views/books/index.html.erb:15 Rendered books/index.html.erb within layouts/application (249.2ms) Completed 200 OK in 2933ms (Views: 2800.7ms | ActiveRecord: 6.8ms) Access log ⬇ Detecting assignment Detecting assignment of instance variables Testing in normal case (No problem case) • Access to /books (Books#index) • app/views/books/index.html.erb • <% @books.each do |book| %> ⬅ Using @books • app/controllers/books_controller.rb:7 • @books = Book.all ⬅ Assignment to @books normally
Case study "Stolen instance variable" Let's back to first problem • @books #=> [] in the view • Find "How to trace assignment of instance variables" in a Rails app, Displaying book data with instance variable @books, but the showing data are incorrect. Correct Current @books #=> []
Started GET "/books" for ::1 at 2019-06-08 13:02:25 +0900 Processing by BooksController#index as HTML @books is assigned in /path_to_app/app/controllers/books_controller.rb:7 index BooksController @books is assigned in /path_to_appapp/controllers/books_controller.rb:8 index BooksController Rendering books/index.html.erb within layouts/application Rendered books/index.html.erb within layouts/application (50.2ms) Completed 200 OK in 3146ms (Views: 2867.5ms | ActiveRecord: 0.0ms) Access log ⬆ Detected!! ⬅ books_controller.rb:8 Detected in books_controller.rb:7,8 Arrest!! ⬅ books_controller.rb:7 Detecting assignment of instance variables Case: A criminal is in controller
Started GET "/books" for ::1 at 2019-06-08 12:55:09 +0900 Processing by BooksController#index as HTML @books is assigned in /path_to_app/app/controllers/books_controller.rb:7 index BooksController Rendering books/index.html.erb within layouts/application Rendered books/index.html.erb within layouts/application (83.2ms) Completed 200 OK in 2881ms (Views: 2742.1ms | ActiveRecord: 0.0ms) ⬇ detected normal case ⬅ books_controller.rb:7 books_controller.rb:7 Detecting normal case in controller But we didn't detect a criminal... Detecting assignment of instance variables There are cases we can't detect them Access log
app/view/books/index.html.erb <% @books = [] %> ... <% @books.each do |book| %> ⬅ A criminal in view The code couldn't detect assignment in view line #=> "<% @books= [] %>\n" The code has erb tags <% %> #=> SyntaxError Detecting assignment of instance variables We can't detect in views. Reason
Remove <% %> tags ↖ line = match_data.captures.first ↙ line.match(/\A\s*<%=*(.*)%>\s*\z/) ⬇ Get the part of (.*) Detecting assignment of instance variables Let's write codes to adopt erb
Started GET "/books" for ::1 at 2019-06-09 09:55:08 +0900 (12.4ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC ↳ /Users/igaiga/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/ log_subscriber.rb:98 Processing by BooksController#index as HTML @books is assigned in /path_to_app/app/controllers/books_controller.rb:7 index BooksController Rendering books/index.html.erb within layouts/application @books is assigned in /path_to_app/app/views/books/index.html.erb:1 _app_views_books_index_html_erb__4042701126060758541_70158372829520 ActionView::CompiledTemplates Rendered books/index.html.erb within layouts/application (76.8ms) Completed 200 OK in 13765ms (Views: 13457.4ms | ActiveRecord: 0.0ms) Arrest!! ↖ index.html.erb:1 <% @books = [] %> Detecting assignment of instance variables Try again Access log
Conclusion Case study "Stolen instance variable" • How to detect assignment of instance variables? • Make trigger using TracePoint :line • Get source file with TracePoint informations • Analyze with RubyVM::AbstractSyntaxTree.parse • type :IASGN means Instance variable assignment • Source codes in this slide • https://github.com/igaiga/RubyConfTaiwan2019 • Published instance_variable_tracer gem • https://github.com/igaiga/instance_variable_tracer
Tracer (in standard library) Outputs a source level execution trace https://ruby-doc.org/stdlib-2.6.3/libdoc/tracer/rdoc/Tracer.html "Tracer" outputs a source level execution trace. Using with Kernel.#set_trace_func in Tracer. log.txt ... #1:/path_to_app/app/views/books/index.html.erb:1:ActionView::CompiledTemplates:-: <%= @books = [] %> ... Tracer.add_filter do |event, file, line, id, binding, klass| file == "/path_to_app/app/views/books/index.html.erb" end Tracer.on Filtering unwanted outputs If we need source code, use File.open method in the filter. (same as TracePoint) ⬆ Executed code ⬆ Source file infomation ⬅ Write this code to the Rails app ⬇ and get log.txt file
About proves: https://bugs.ruby-lang.org/projects/ruby/wiki/DTraceProbes Attach running process, prove something, and run action DTrace Example: • Puts log when method calls are made • Counting method calls DTrace is faster than TracePoint, but we need "sudo" to run. https://tenderlovemaking.com/2011/12/05/profiling-rails-startup-with-dtrace.html
ObjectSpace.allocation_sourcefile Object traceability Returns the source file origin from the given object. We need objspace standard library ObjectSpace - built-in class objspace - Standard library, to add some methods to ObjectSpace ObjectSpace.allocation_sourcefile(object) - source file the object was made ObjectSpace.allocation_sourceline(object) - line number of the source file #=> {"path_to_app/app/views/books/index.html.erb"=>1} ⬅ start tarcing http://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html
signal & trap Stop the world ⬅ This block called when a signal comming Occurs info signal In macOS ctrl-T or $ kill -s info [pid] http://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html
application_controller.rb before_action { g "#{self.class.name}##{action_name}" } Only a line the gem doing Displays requested controller and action name station_signage gem with g https://github.com/igaiga/station_signage
References • Hijacking Ruby Syntax in Ruby https://www.youtube.com/watch?v=04HGQEw3A6Y • †Ruby Black Magics Scriptures† †Rubyࠇຐज़ܦయ† (ja) https://speakerdeck.com/joker1007/rubyhei-mo-shu-jing-dian • About RubyVM::AbstractSyntaxTree::Node (ja) https://qiita.com/siman/items/3017ed399ded43229189 •I am a puts debugger http://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html • Ruby Debugging Magic Cheat Sheet https://www.schneems.com/2016/01/25/ruby-debugging-magic-cheat-sheet.html That's all. And tell me more about your debugging experience!
p self #=> ޒेཛྷ໌/igaiga Ruby and Rails freelancer in Tokyo 5xRuby Japan Technical Adviser Working in pixiv, GMO Pepabo (and others) I've wrote some Ruby books in Japan https://twitter.com/igaiga555
igaiga
ivargrimstad
m_coder
schroneko
pluu
pospome
jrsaruo
cocoeyes02
shibe23
nozaki
akitotsukahara
hirodragon112
star_zero
morganepeng
pedronauck
davidbonilla
jrom
danielanewman
smashingmag
thekraken
philhawksworth
jponch
mongodb
samanthasiow
aki_iinuma