Road to white mages

RubyConf Taiwan 2019
2019.7.26

Transcript

1. Road to white mages നຐज़ࢣಓ RubyConf Taiwan Jul 26, 2019 Kuniaki Igarashi / ޒेཛྷ๜໌ twitter: @igaiga555
2. 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
4. •"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
5. 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
6. 2 great black mages in Japan RubyKaigi2018 joker1007, Satoshi "moris" Tagomori tagomoris https://youtu.be/04HGQEw3A6Y
7. 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
8. 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
9. •"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
10. "How to talk with objects" • Ruby basics for debugging • Ruby objects tell us a lot of informations ⏰7
11. 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
12. Who are you? To know objetcs •Kernel#class method • gets class of object •Kernel#object_id method • gets object's serial numbers
13. 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
14. 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
15. 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
16. 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
17. 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.
18. How to change/get objects • instance_variables • get instance variable's names • instance_variable_get, instance_variable_set • get/set instance variables • instance_eval, class_eval • blocks are executed in receiver objects • useful to modify instance variable • useful to call private methods • to write easier than send method • binding • changes local variables • RubyKaigi2018 joker and moris • https://youtu.be/04HGQEw3A6Y
19. 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
20. 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
21. Case study "Stolen instance variable" ⏰15
22. 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 #=> []
23. "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.
24. 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 ⬇
25. 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
26. 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.
27. 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
28. 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::Node:SCOPE@1:0-1:33>
29. 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
30. node #=> (SCOPE@1:0-1:33 tbl: [] args: nil body: (IASGN@1:4-1:33 :@hi (STR@1:10-1:33 "hi(ŇŋωŋŇ)ϊ"))) node.class #=> RubyVM::AbstractSyntaxTree::Node node.type #=> :SCOPE node.children #=> [[], nil, (IASGN@1:4-1:33 :@hi (STR@1:10-1:33 "hi(ŇŋωŋŇ)ϊ"))] node.children.last.class #=> RubyVM::AbstractSyntaxTree::Node node.children.last.type #=> :IASGN RubyVM::AbstractSyntaxTree.parse(" @hi = \"hi(ŇŋωŋŇ)ϊ\"\n") #=> RubyVM::AbstractSyntaxTree::Node object RubyVM::AbstractSyntaxTree::Node AST::Node object structure Find methds with node.methods
31. node.children.last.class #=> RubyVM::AbstractSyntaxTree::Node node.children.last #=> (IASGN@1:4-1:33 :@hi (STR@1:10-1:33 "hi(ŇŋωŋŇ)ϊ")) node.children.last.type #=> :IASGN RubyVM::AbstractSyntaxTree.parse(" @hi = \"hi(ŇŋωŋŇ)ϊ\"\n") IASGN #=> Assignment of instance variable Reference: RubyVM::AbstractSyntaxTree::Node - siman (ja) https://qiita.com/siman/items/3017ed399ded43229189 RubyVM::AbstractSyntaxTree::Node AST::Node IASGN #=> Assignment of instance variable
32. RubyVM::AbstractSyntaxTree Detecting instance variable assignment with AST::Node information Current: Detecting all instance variable assignment Next: Detecting only specified instance variable name ⬅ Check AST node is instance variable assingment Detected it! (ʆɾωɾ´)b
33. 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
34. 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
35. Detecting assignment of instance variables We did it! (ʆɾωɾ´)b Next, let's back to the Rails app and try to use the technique.
36. 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")
37. 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
38. 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 #=> []
39. 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
40. 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
41. 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
42. 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
43. 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
44. 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
45. White magic survey articles Other topics • Tracer • DTrace • ObjectSpace#allocation_sourcefile • signal & trap • g ⏰32
46. 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
47. 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
48. 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
49. 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
50. g gem https://github.com/jugyo/g p method displaying on notification
51. station_signage gem with g https://github.com/igaiga/station_signage
52. 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
53. 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!
54. 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