Debugging (PHP) Applications

PHP Benelux, 28. 1. 2018
© David Buchmann, Liip AG

twitter.com/bramcohen/status/51714087842877440

Organisation

Introduction
Tutorial Application
Bug Hunting
--- break ---
More Bug Hunting
Bug Prevention
Bug Detection
Wrap-Up

Introduction

Debugging

Methodical guessing
Narrowing down the problem
Quickly validate a guess

Security Bugs

Missing access control
Functionality exposed: e.g. eval(), exec(),
string concatenation for SQL queries
Missing validation of input

This workshop focuses on finding the location of bugs. Scanning for security vulnerabilities is worth its own Workshop.

Bug Report

Look at the list of open bugs if already reported

Title

Platform/Environment
What did you do - how to reproduce?
What did you expect to happen?
What was the actual result?
Screenshot if visual, copy console output if text (use ``` in github)

For OSS: Pull request with failing test, or even a fix?

Respect!

Demo Tutorial Application

Import data from CSV into a relational database
Doctrine ORM models
Website that shows imported data

Demo Tutorial Application

http://debugging.lo

vagrant up
vagrant ssh

Bug Hunting

Usage

git reset --hard
git checkout [branchname]

If you get random errors about files in /vagrant/var/cache/dev/ not found, do:

rm -rf var/cache/dev/

I often use obvious errors to illustrate a case. Real bugs will often be more complicated, but the strategies apply...

[b1] Bug 1

http://debugging.lo

Look at exception message

[b1] RTFEM: Wrong Typehint

Cannot autowire service "App\Importer\Likes": argument "$em" of method "__construct()" references class "Doctrine\ORM\EntityManager" but no such service exists. Try changing the type-hint to one of its parents: interface "Doctrine\O RM\EntityManagerInterface", or interface "Doctrine\Common\Persistence\ObjectManager".

The exception message suggests a solution
Try that suggestion

✔ Exceptions are your friends, read them carefully.

[b2] Bug 2

bin/console app:import

Argument -v makes output more verbose.
Look at the stack trace.

[b2] Stacktrace

App\Importer\Mapper\LikeMapper->map() at .../Likes.php:49
App\Importer\Likes->import() at .../AppImportCommand.php:60
App\Command\AppImportCommand->execute() at .../Command.php:252 ...

Figure out what we are calling
Check where the data comes from
Check what would make sense

$this->productRepository->find($data['CustomerId']);

✔ Exception stack trace provides context of errors

[b3] DDD: Die Driven Debugging

bin/console app:import

The CustomerMapper checks if customer id already exists.
Add die('cache')|found|new in CustomerMapper::map

[b3] DDD

$customer = $this->customerRepository->find($data['ProductId']);

Ok if you have a confident guess
Quick way to ensure you look at the correct place
Stop after second attempt though
ProTip™ do not commit the die() to git

✔ At most, use die() to check if you are in the expected place of the code

[b4] Use proper exceptions

bin/console app:import

Search code for "oops"
Search for die( and throw exceptions with decent messages

[b4] Use proper exceptions

An exception should tell what happened
Not overly verbose
But provide enough context to be useful
! Careful with user input / large data

✔ do not make your collegues and your future self hate you

Demo: Step by step debugger

                ; config to run the remote debugger
                xdebug.remote_enable=1
                xdebug.remote_autostart=1
                xdebug.remote_connect_back=1
                xdebug.idekey="XDEBUG-DRIFTER"

Demo: Step by step debugger

Configure your IDE
Set IDE to listen to debugging
ifconfig to find IP of vboxnet1
php -d xdebug.remote_host=10.10.10.1 ./bin/console app:import
https://blog.theodo.fr/2016/08/configure-xdebug-phpstorm-vagrant/

[b5] Segfault/Infinite Loops

bin/phpunit

At which test does it hang? Try --debug

[b5] Infinite Loop

Last line says CsvProductLoaderTest::testLoadFileNotFound

✔ progressive report to see which test fails hard

[b6] Search codebase for context

http://debugging.lo

Look at the page source for some context, then search the codebase to see what happens around it.

[b6] Search codebase for context

<h2 style="color:green;">Found {{ customer_count }} customers {{ render(controller('App\\Controller\\HomeController::extra')) }}

Set a breakpoint in HomeController::extra

✔ Program output can provide context where to look for errors

[b7] Search in logfiles

bin/console app:import --reset -q
http://debugging.lo shows only 99 customers instead of 100

Search for non-debug messages in logfile:

echo '' > var/log/dev.log
bin/console app:import --reset -q
cat var/log/dev.log | grep -v DEBUG

[b7] Search in logfiles

app.WARNING: Invalid number of columns for App\Importer\Loader\CsvLikeLoader at CSV row 26

Look at the CSV file data/likes.csv
Line 26 has a comma in the name and no quotes
Tell provider of this CSV to fix their thing

✔ Search logfiles for id's or message fragments. It helps if you know when the problem happened.

[b8] Unit Test (for debugging)

We built a (horrible) security into our website. But its faulty:

http://debugging.lo/?secret=I%20am%20David
http://debugging.lo/?secret=David

Build a unit test for the HomeController::index method to cover all cases.

[b8] Unit Test

if (!stripos($secret, 'david')) {

Use false === stripos() and 0 === stripos() to prevent errors
(And never do security like this! Use a form login or basic auth, read up on token authentication.)

✔ Build a unit test when debugging a specific component. Often you want to keep that test afterwards.

[b9] Do not assume

bin/phpunit
all green, great?
run bin/console app:import

The unit test CustomerMapperTest got it wrong with mocking.

[b9] Do not assume

CustomerMapperTest

$this->repository
    ->expects($this->once())
    ->method('find')
-   ->with('1607080270099')
+   ->with('Quyn Goff')
    ->will($this->returnValue(null));

Mocking in unit tests can hide errors
We even have an integration test
Unfortunately it does not recreate the specific situation

✔ Be wary of mocking.

[ba] git bisect

http://debugging.lo
bin/phpunit But it used to work!!

https://www.sumologic.com/blog/devops/who-broke-my-test-a-git-bisect-tutorial/

[ba] git bisect

git bisect start
git bisect bad ba      # broken version
git bisect good ba-1.0 # known working version

# => now you are in the middle of the history

# repeat
# run bin/phpunit and see if it goes through
# if so
git bisect good
# else
git bisect bad

[ba] git bisect

git show 09f8efd68cd535fc670c687081a77a5c4a32f0e8
- if ('\App\Entity\Customer' !==
-     $this->options['customer_class']
+ if (Customer::class !==
+     $this->options['customer_class']
  ) {
      die();

Bonus points: What is the problem?

✔ If you know the last good state and have an easy way to decide between good and bad, git bisect is very efficient at localizing a problematic commit.

[bb] Symfony debug toolbar

http://debugging.lo
New feature: Only show expensive products

Do we have expensive products in the CSV/database?
What query has been run?

Symfony Debug Toolbar or tail var/log/dev.log

[bb] Symfony debug toolbar

WHERE p0_.price > 10 AND p0_.price < 10

Somebody has been tired...

✔ Look at the actual SQL query that has been executed.

[bb] Logging SQL

Set up doctrine dbal logging
Use a PHP aware profiler (blackfire.io, tideways.io)
Enable query logging in MySQL (beware, this will be verbose):

SET GLOBAL log_output = "FILE";
SET GLOBAL general_log_file = "/path/logfile.log";
SET GLOBAL general_log = 'ON';

[bc] How did this ever work?

bin/phpunit

This clearly does not do what was expected
You are sure it did work on the server

Visit 3v4l.org and run the suspicious bit of code.

[bc] How did this ever work?

http://php.net/manual/en/migration70.incompatible.php #migration70.incompatible.strings.hex

✔ If you suspect PHP version issues, 3v4l.org is a great tool to quickly check.

[bd] Using linters

We added .travis.yml for automated testing.
travis-ci complains about the file, can't handle it.
What is wrong with the file?

Symfony provides the lint:yaml command

[bd] Using linters

Indentations in YAML are hard
Not all tools provide good error messages when syntax errors occur
Alternatively, there are web sites like https://jsonformatter.org/yaml-validator

✔ Linting helps to find syntax errors.

[be] Demo: Performance issue

«Premature optimization is the root of all evil.» (Donald Knuth)

"Something" is slow
Before we look at any code, use a tool to identify what is slow

php -d xdebug.profiler_enable=1 bin/console app:import
(xdebug.profiler_output_dir must exist, it is not created automatically)
KCacheGrind

[be] Demo: Performance issue

Alternatives:

xhprof (for PHP 7, use https://github.com/tideways/php-profiler-extension) and a frontend for xhprof data.
SaaS like blackfire.io (or tideways.io, newrelic)

✔ Find the slow part rather than optimize random bits of code.

[bf] Memory issue

bin/console app:import --reset

Start logging memory_get_usage() (or use blackfire.io)

[bf-fixed] Memory issue

We flush customers in batches

PHP request/response cycle often avoids problem
Give up references to let garbage collector work
Beware of naive array caches
https://tideways.io/profiler/blog/how-to-optimize-the-php-garbage-collector-usage-to-improve-memory-and-performance

✔ Memory issues are tricky, they often depend on the data. Avoid keeping unnecessary references.

Other Strategies

Potential vendor bugs: composer install --prefer-source
Google generic part of error message
Ask collegues, ask on twitter (3v4l.org, gist)
Also: Rubberducking
Take a break