Debugging (PHP) Applications



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

twitter.com/bramcohen/status/51714087842877440

Organisation




Introduction

Debugging

Security Bugs


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


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


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

$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']);

✔ 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


✔ 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

  1. Configure your IDE
  2. Set IDE to listen to debugging
  3. ifconfig to find IP of vboxnet1
  4. php -d xdebug.remote_host=10.10.10.1 ./bin/console app:import
  5. 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')) }}


✔ 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


✔ 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')) {


✔ 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));
✔ 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();
✔ 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
Symfony Debug Toolbar or tail var/log/dev.log

[bb] Symfony debug toolbar

WHERE p0_.price > 10 AND p0_.price < 10
✔ Look at the actual SQL query that has been executed.

[bb] Logging SQL

SET GLOBAL log_output = "FILE";
SET GLOBAL general_log_file = "/path/logfile.log";
SET GLOBAL general_log = 'ON';
See also: Slow query log

[bc] How did this ever work?

bin/phpunit
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

Symfony provides the lint:yaml command

[bd] Using linters

✔ Linting helps to find syntax errors.

[be] Demo: Performance issue

«Premature optimization is the root of all evil.» (Donald Knuth)
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:
✔ 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
✔ Memory issues are tricky, they often depend on the data. Avoid keeping unnecessary references.

Other Strategies

Bug Prevention

Software Lifecycle

(Agile too, just not as isolated phases)

How to prevent errors

Testing, Continous Integration

Code Coverage

bin/phpunit --coverage-html public/coverage
http://debugging.lo/coverage/index.html
Run only tests/Functional/Controller/HomeControllerTest.php

Code Coverage

✔ Looking at code coverage helps you identify untested parts of your code.

[p1] Static code analysis

vendor/bin/phpstan analyse --level 1 src/
Fix the reported bug, then try raising the level to find more issues.

[p1] Static code analysis

---- --------------------------------------------
Line src/Importer/Mapper/CustomerMapper.php
---- --------------------------------------------
 49  Class App\Importer\Mapper\Customr not found.
---- --------------------------------------------
✔ Static code analyzers push you to write clean code. Sometimes they also find straight-up bugs.

Clean Code

Clean Code

if (!$condition) {
    // do stuff
} else {
    return $default;
}
return $result;
            
if ($condition) {
    return $default;
}
// do stuff
return $result;

Clean Code

foreach ($list as $valueSet) {
    foreach ($valueSet as $key => $value) {
        if (0 === strpos($value, $searched)) {
            $result = $key;
            break(2);
        }
    }
}

Clean Code

function findValue($list, $searched) {
    foreach ($list as $valueSet) {
        foreach ($valueSet as $key => $value) {
            if (0 === strpos($value, $searched)) {
                return $key;
            }
        }
    }
}
$result = findValue($list, $searched);
Note: Method calls add overhead, do not exagerate.

[p2] Mess detection

vendor/bin/phpmd src/ text codesize
This is no pretty sight

[p2] Mess detection

✔ A mess detector can help you to avoid hard to understand and hard to test code

Mess detection

Source: https://twitter.com/_cingraham/status/946462990504681472

Yoda style expressions

if ('404' = errorCode) {
Syntax error instead of accidental value assignment

[p3] Validate - fail early

bin/phpunit => all green
bin/console app:import
Add sanity checks in the CSV loader

[p3] Validate - fail early

The file configuration got swapped, the code tries to load the wrong file.
✔ The earlier you fail, the closer to the source of the problem you are. That simplifies debugging tremendously.

Demo: Symfony OptionsResolver

public function __construct(array $options = [])
{
    $resolver = new OptionsResolver();
    $resolver->setRequired([
        'template',
    ]);
    $resolver->setDefault('choice', 'a');
    $resolver->setAllowedValues(
        'choice',
        ['a', 'b', 'c']
    );

    $this->options = $resolver->resolve($options);
}

[p4] Make it difficult to make mistakes

bin/phpunit
What is wrong?

[p4] isset vs array_key_exists

if (isset($this->customer[$data['Id']])) {
    $customer = $this->customers[$data['Id']];
    $customer->name = $data['Name'];

    return $customer;
}
    
if (array_key_exists($data['Id'], $this->customers))
✔ isset hides errors, array_key_exists does not use any magic

Make your code understandable

Make your code understandable (II)

https://twitter.com/legacy_coder/status/880138870460997632

Naming things

function createNewUser($username, $dontEscape=false)

function createUser($username, $escape=true)

Bug Detection

Monitor

Monitoring Tools

Alerting

Logging

Log Levels

main:
    type: fingers_crossed
    action_level: error
    handler: nested
    excluded_404s:
        # regex: exclude 404 errors from the logs
        - ^/
nested:
    type: stream
    path: "/var/log/symfony.log"
    level: debug

[d1] Demo: Log Channels

Separate some logs into a channel
bin/console app:import --reset -v
bin/console app:import --reset -vv
bin/console app:import --reset -vvv
App\Importer\Mapper\LikeMapper:
    arguments:
        - '@logger'
    tags:
        -
          name: monolog.logger
          channel: like_mapper

debug_like_mapper:
    type: console
    channels: ["like_mapper"]
    level: debug
    # console logger checks log level against
    # console output verbosity
    verbosity_levels:
        VERBOSITY_QUIET: ERROR
        VERBOSITY_NORMAL: ERROR
        VERBOSITY_VERBOSE: DEBUG
        VERBOSITY_VERY_VERBOSE: DEBUG
        VERBOSITY_DEBUG: DEBUG



Wrap-Up

https://github.com/symfony/symfony/pull/18547

Types of Bugs

Types of Bugs (II)

Cem Kaner's appendix of "Common Software Errors" (Kaner et al)

Distributed System


Questions / Input / Feedback ?


https://joind.in/talk/1e8f7


Twitter: @dbu