Road to white mages

Road to white mages

RubyConf Taiwan 2019
2019.7.26

5ad0bb268dd2605b09165d464308cb7e?s=128

Kuniaki IGARASHI

July 26, 2019
Tweet

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
  3. None
  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
  55. None