Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

No content

Slide 4

Slide 4 text

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

Slide 5

Slide 5 text

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

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

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

Slide 12

Slide 12 text

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

Slide 13

Slide 13 text

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

Slide 14

Slide 14 text

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

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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.

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

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

Slide 20

Slide 20 text

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

Slide 21

Slide 21 text

Case study "Stolen instance variable" ⏰15

Slide 22

Slide 22 text

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

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

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 ⬇

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

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.

Slide 27

Slide 27 text

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

Slide 28

Slide 28 text

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

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

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

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

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

Slide 35

Slide 35 text

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

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

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

Slide 45

Slide 45 text

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

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

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

Slide 49

Slide 49 text

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

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

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!

Slide 54

Slide 54 text

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

Slide 55

Slide 55 text

No content