Every once in a while it happens that you have a tricky bug, and when it does you risk to lose hours or even days fixing it.
Bugs are supposed to be part of software development process and what I learned along the years is that when you get really comfortable in your development environment (language, framework, deployment type, etc), the time spent solving bugs is really limited, because you work inside your comfort zone (technology-wise).
Yet, sometimes there is that one bug that makes you lose your shit after a whole afternoon spent looking for the root cause. In my experience, bugs that I introduce are generally very quick and easy to spot and fix. But the real challenge is finding bugs in other people’s code like third party libraries, PHP extensions or even PHP itself.
When strange things happen, the ritual is the same every time: fire up the debugger on PHPStorm, place a few breakpoints and see what happens.
Yesterday it was different, though.
After doing a few changes to the codebase and reloading the page on the browser, I started getting straight HTTP 500 errors which weirdly enough weren’t caught by the Zen Framework’s error/exception handlers and the apache error log didn’t contain any error.
Seems like apache might be crashing, let’s see.
$ sudo less /var/log/syslog...Mar 1 15:59:15 redokunvm kernel: [593714.307281] Out of memory: Kill process 30901 (apache2) score 639 or sacrifice childMar 1 15:59:15 redokunvm kernel: [593714.308664] Killed process 30901 (apache2) total-vm:2707492kB, anon-rss:1852200kB, file-rss:8024kB...
Yup, out of memory error, even though the operation performed by the request was not memory intensive at all. Yet, the memory limit imposed via ini_set should have caught that. Unless it’s something happening in the PHP core or on one of its extensions.
In these cases you have a few options like:
- adding log entries on every step and try to find what is causing the memory leak
- open the debugger and add a few breakpoint, see what happens
Looking at the application logs it was clear that the problem was generated while saving a Doctrine entity to DB. But debugging Doctrine would require quite some time, so I decided to try another approach.
Meet strace
strace is a debugging tool that analyses all the syscalls that a certain process makes to the kernel. This can come very handy in my case because I can see what exactly is doing the PHP app when things break.
So let’s fire up strace and monitor all the apache child:
$ ps h --ppid $(cat /var/run/apache2/apache2.pid) | awk '{print"-p " $1}' | xargs sudo strace -o strace.txt
After loading the webpage again I looked at strace.txt and found this:
open("/mnt/hgfs/php/redokun/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOException.php", O_RDONLY) = 25...open("/mnt/hgfs/php/redokun/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/DriverException.php", O_RDONLY) = 25...mremap(0x7f4b8b111000, 188416, 192512, MREMAP_MAYMOVE) = 0x7f4b8b0e2000mremap(0x7f4b8b0e2000, 192512, 196608, MREMAP_MAYMOVE) = 0x7f4b8b0e2000mremap(0x7f4b8b0e2000, 196608, 200704, MREMAP_MAYMOVE) = 0x7f4b8b0e2000
(mremap was called thousand of times without stopping)
Clearly the mremap syscall was allocating more and more memory until the process was killed by the kernel.
So looking at the last syscalls it seemed that the leak had something to do with a PDOException exception that was autoloaded just before (along with DriverException which is an interface that the exception implements).
After putting a few breakpoint inside PDOException.php I realized that the exception was indeed prepared and thrown by Doctrine but, it was never caught inside the Doctrine\DBAL\Statement::execute() method which contains a try/catch.
Since this is clearly something related to an extension or PHP itself, I tried disabling the extensions. The most likely culprit was XDebug, which I’m sure has some kind of hook that is triggered when an exception is created or thrown.
And sure enough, after disabling XDebug, I could finally see the exception and fix it.
After some more digging, I found that it was not a bug inside XDebug, but rather a misconfiguration which forced XDebug to crash.
Here is the line that I had to remove inside my application that apparently was generating the memory leak: ini_set("xdebug.var_display_max_data", "-1");
Using strace to debug PHP applications may seem like an extreme measure, but given the ease of use, it can definitely be one of the tools to use when looking for nasty bugs like this one.
Hacker Noon is how hackers start their afternoons. We’re a part of the @AMIfamily. We are now accepting submissions and happy to discuss advertising & sponsorship opportunities.
To learn more, read our about page, like/message us on Facebook, or simply, tweet/DM @HackerNoon.
If you enjoyed this story, we recommend reading our latest tech stories and trending tech stories. Until next time, don’t take the realities of the world for granted!