Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Road to white mages

Road to white mages

RubyConf Taiwan 2019
2019.7.26

Kuniaki IGARASHI

July 26, 2019
Tweet

More Decks by Kuniaki IGARASHI

Other Decks in Programming

Transcript

  1. Road to white mages
    നຐज़ࢣಓ
    RubyConf Taiwan
    Jul 26, 2019
    Kuniaki Igarashi / ޒेཛྷ๜໌
    twitter: @igaiga555

    View Slide

  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

    View Slide

  3. View Slide

  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

    View Slide

  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

    View Slide

  6. 2 great black mages in Japan
    RubyKaigi2018
    joker1007, Satoshi "moris" Tagomori tagomoris
    https://youtu.be/04HGQEw3A6Y

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  10. "How to talk with objects"
    • Ruby basics for debugging
    • Ruby objects tell us a lot of informations
    ⏰7

    View Slide

  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

    View Slide

  12. Who are you?
    To know objetcs
    •Kernel#class method
    • gets class of object
    •Kernel#object_id method
    • gets object's serial numbers

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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.

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  21. Case study
    "Stolen instance variable"
    ⏰15

    View Slide

  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 #=> []

    View Slide

  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.

    View Slide

  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 ⬇

    View Slide

  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

    View Slide

  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.

    View Slide

  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

    View Slide

  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")
    #

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  35. Detecting assignment of instance variables
    We did it!
    (ʆɾωɾ´)b
    Next, let's back
    to the Rails app
    and try to use
    the technique.

    View Slide

  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")

    View Slide

  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

    View Slide

  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 #=> []

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  45. White magic survey articles
    Other topics
    • Tracer
    • DTrace
    • ObjectSpace#allocation_sourcefile
    • signal & trap
    • g
    ⏰32

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  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

    View Slide

  50. g gem
    https://github.com/jugyo/g
    p method displaying on notification

    View Slide

  51. station_signage gem with g
    https://github.com/igaiga/station_signage

    View Slide

  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

    View Slide

  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!

    View Slide

  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

    View Slide

  55. View Slide