Debugging: The Science of Deduction (2014)

As presented at Øredev 2014

Transcript

1. THE SCIENCE OF DEDUCTION dsucher@gmail.com • @DanielleSucher DEBUGGING
2. "People write programs without any expectation that they will be right the first time." ! - David Lorge Parnas
4. Let’s start simple.
5. When you get an error message
6. “Oh, I think I know what went wrong..!”
7. NO.
8. READ THE ERROR MESSAGE
9. /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/attribute_assigner.rb:14:in `tap'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/attribute_assigner.rb:14:in `object'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/evaluation.rb:12:in `object'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/strategy/build.rb:9:in `result'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory.rb:42:in `run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory_runner.rb:23:in `block in run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/activesupport-4.0.1/ lib/active_support/notifications.rb:161:in `instrument'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory_runner.rb:22:in `run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/strategy_syntax_method_registrar.rb:19:in `block in define_singular_strategy_method'! /Users/stan/projects/rails4/spec/models/project_spec.rb:21:in `block (4 levels) in <top (required)>'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `block (2 levels) in let'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `fetch'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `block in let'!
10. How do you find the important stuff?
11. Start at the top.
12. Skim for lines that refer to your project’s codebase
13. /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/attribute_assigner.rb:14:in `tap'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/attribute_assigner.rb:14:in `object'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/evaluation.rb:12:in `object'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/strategy/build.rb:9:in `result'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory.rb:42:in `run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory_runner.rb:23:in `block in run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/activesupport-4.0.1/ lib/active_support/notifications.rb:161:in `instrument'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/factory_runner.rb:22:in `run'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/factory_girl-4.2.0/ lib/factory_girl/strategy_syntax_method_registrar.rb:19:in `block in define_singular_strategy_method'! /Users/stan/projects/rails4/spec/models/project_spec.rb:21:in `block (4 levels) in <top (required)>'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `block (2 levels) in let'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `fetch'! /Users/stan/.rvm/gems/ruby-1.9.3-p448@rails4/gems/rspec-core-2.14.5/ lib/rspec/core/memoized_helpers.rb:199:in `block in let'!
14. If you’re in a JVM language…
15. look for the “Caused By” Exception in thread "main" java.lang.NoClassDefFoundError: org/apache/commons/logging/LogFactory at org.springframework.context.support.AbstractApplicationContext.<init>( AbstractApplicationContext.java:160) at org.springframework.context.support.AbstractRefreshableApplicationContext.<init>( AbstractRefreshableApplicationContext.java:89) at org.springframework.context.support.AbstractRefreshableConfigApplicationContext.<init>( AbstractRefreshableConfigApplicationContext.java:59) at org.springframework.context.support.AbstractXmlApplicationContext.<init>( AbstractXmlApplicationContext.java:61) at org.springframework.context.support.ClassPathXmlApplicationContext.<init>( ClassPathXmlApplicationContext.java:136) at org.springframework.context.support.ClassPathXmlApplicationContext.<init>( ClassPathXmlApplicationContext.java:83) at com.springinaction.knights.KnightMain.main(KnightMain.java:12) Caused by: java.lang.ClassNotFoundException: org.apache.commons.logging.LogFactory at java.net.URLClassLoader$1.run(URLClassLoader.java:366) at java.net.URLClassLoader$1.run(URLClassLoader.java:355) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:354) at java.lang.ClassLoader.loadClass(ClassLoader.java:423) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) at java.lang.ClassLoader.loadClass(ClassLoader.java:356) ... 7 more
16. look for the “Caused By” Exception in thread "main" java.lang.NoClassDefFoundError: org/apache/commons/logging/LogFactory at org.springframework.context.support.AbstractApplicationContext.<init>( AbstractApplicationContext.java:160) at org.springframework.context.support.AbstractRefreshableApplicationContext.<init>( AbstractRefreshableApplicationContext.java:89) at org.springframework.context.support.AbstractRefreshableConfigApplicationContext.<init>( AbstractRefreshableConfigApplicationContext.java:59) at org.springframework.context.support.AbstractXmlApplicationContext.<init>( AbstractXmlApplicationContext.java:61) at org.springframework.context.support.ClassPathXmlApplicationContext.<init>( ClassPathXmlApplicationContext.java:136) at org.springframework.context.support.ClassPathXmlApplicationContext.<init>( ClassPathXmlApplicationContext.java:83) at com.springinaction.knights.KnightMain.main(KnightMain.java:12) Caused by: java.lang.ClassNotFoundException: org.apache.commons.logging.LogFactory at java.net.URLClassLoader$1.run(URLClassLoader.java:366) at java.net.URLClassLoader$1.run(URLClassLoader.java:355) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:354) at java.lang.ClassLoader.loadClass(ClassLoader.java:423) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) at java.lang.ClassLoader.loadClass(ClassLoader.java:356) ... 7 more
17. Read the line number
18. And read the actual error message!
19. google the error (no, really, you’re not smarter than google)
20. Unexpected Behavior
21. “I don’t guess. I observe.”
22. “And once I’ve observed...”
23. “I deduce.”
24. Formulate a hypothesis. Try to disprove it. ! Repeat as needed.
25. Where do you start looking?
26. The Streetlight Effect searching where the keys fell vs searching where the light is
27. ! ! Start looking where the light is
28. First test the theories you can disprove the fastest
29. To test your hypotheses, you need to reproduce the bug
30. If you can’t reproduce the bug, what’s different about your environment?
31. Watch somebody else reproduce the problem.
32. Sometimes it’s all in the timing
33. Even partial patterns can give you useful data
34. the 500 mile bug ! http://www.ibiblio.org/harris/ 500milemail.html
35. Try to break things down into smaller, self-contained, pieces.
36. Don’t even try to understand everything
38. Miller’s Law The average person can only hold ! 7 ± 2 ! items in working memory
39. It’s okay to think of the rest of the system as a black box
40. Break apart methods so you can test smaller chunks of logic separately
41. Comment out parts of your code so you can focus on one piece at a time
42. Refactoring and adding tests ! (or even just fixing typos) ! keeps you focused and improves your understanding
43. With really gnarly code write tests to document existing behavior
44. find the minimal case needed to reproduce the failure
45. QuickCheck Generators, Properties, and Minimization
46. QuickCheck property("reverse") = forAll { s: String => reverse(reverse(s)) == s }
47. "...what are the facts, and what is the truth that the facts bear out?" ! - Bertrand Russell
48. Is the method you’re looking at even being called at all?
49. def might_be_called puts “IN MIGHT_BE_CALLED” puts caller # ... end
50. “What they don’t confess to is almost always more interesting.”
51. What are the actual inputs your method is receiving?
52. Maybe you think you’re getting nil, but you’re getting ‘’ or [‘’] instead
53. Is there a rescue in the way, swallowing useful errors?
54. What is the state of the universe?
55. Follow the money logs $ tail -f log/whatevs.log
56. Does doing things in a different order lead to different results?
57. Possible Ordering Problems Methods with side effects Rails autoload order Database left in a dirty state
58. Clean out your environment (if at all possible)
59. Make the problem more concrete
60. Sketch things out
61. Wave your hands around in the air ! placing pieces of your system in imaginary 3d space
62. “I need to go to my mind palace.”
63. Question your assumptions. ! (Write a list or even an informal proof, if necessary.)
64. Rubber duck debugging
65. Trust no one.
67. “Without a debugger, you basically have to go to the next step; understand what the program does.” ! - Linus Torvalds
68. print statement debugging puts “*” * 20 puts “foo: #{foo.inspect}” puts “*” * 20
69. Where is this method defined? m = Foo.new.method(:do_stuff) m.source_location ! => [filename, line_number]
70. What types are being imputed? scalac -Xprint:typer Foo.scala
71. “Ideas are tested by experiment. That is the core of science.” ! - Zombie Richard Feynman (via xkcd)
72. Experiment with small pieces of the code a REPL
73. Focus on what’s changed since the problem started
74. git churn --since='3 days ago' ! https://github.com/ garybernhardt/dotfiles/blob/ master/bin/git-churn
75. A few more Git tricks
76. test on a different branch or a different commit
77. git bisect ! binary search through your commits to figure out when the problem started!
78. Running git bisect manually $ git bisect start $ git bisect good SHA $ git bisect bad HEAD
79. Running git bisect automatically $ git bisect start HEAD HEAD~10 $ git bisect run rspec spec/
80. git blame (not actually for blaming people!)
81. The person who wrote this code may have been an idiot. ! Or they may have been a mad genius.
82. Look at the original context $ git blame -L(range) filename ! $ git show SHA
83. But what about whitespace changes? $ git blame -w filename ! (ignores whitespace)
84. But what about lines that were just copied or moved? $ git blame -wCCC filename ! -w ignores whitespace -C detects moved/copied lines -CCC is like -C, but tries harder
85. $ git log -p ! Includes patches, not just commit messages. ! You can search with /search_string
86. $ git log -S “test string” ! Lists only commits where that string was added or deleted
87. Debuggers
88. ls - list methods on an object cd - into objects wtf? - backtrace show-doc - prints docs show-method - prints source whereami - no really Pry
89. Conditional Breakpoints binding.pry if @whatevs
90. Watchpoints See where a particular field is accessed or modified
91. WHEN THINGS GET REALLY WEIRD
92. This shouldn’t make a difference, but let’s try it just in case...
94. Both conditions ran…
95. Maybe it’s cosmic rays http://sip.cs.princeton.edu/pub/ memerr.pdf ! http://thoughtcrime.crummy.com/ 2009/Error.html
96. It doesn’t count if you’re right by accident
97. “That’s clever. Is it clever?” “...why is it clever?”
98. If you don’t understand the cause of the problem, it’s not fixed, because you can’t predict when it might come up again.
99. Don’t be afraid to read the source
100. $ bundle open gem_name
101. livegrep
102. livegrep https://github.com/livegrep/ livegrep ! http://livegrep.com/search/linux
103. occasionally the compiler (Rarely! But it happens.)
104. diverging implicit expansion Two implicits diverged in a yellow wood
105. grep the compiler Reading the source can be easier than reading StackOverflow
106. What’s up with those implicits, anyways? scalac -Xlog-implicits Foo.scala
109. “You know my methods, Watson.”
110. THE SCIENCE OF DEDUCTION dsucher@gmail.com • @DanielleSucher DEBUGGING thank you!