Did a bunch more cowboy coding today as I call it (coding in vi on production). Gather 'round kiddies, uncle Logan's got a story fer ya…

First things first, disclaimer: I'm no sysadmin. I respect sysadmins and the work they do, but I'm the first to admit my strengths definitely lie more in writing programs rather than running servers.

Anyhow, I recently inherited someone else's codebase (the story of my profession career, but I digress) and let me tell you this thing has amateur hour written all over it. It's written in PHP and JavaScript by a self-taught programmer who apparently discovered procedural programming and decided there was nothing left to learn and stopped there (no disrespect to self-taught programmers).

I could rant for days about the various problems this codebase has, but today I have a very specific story to tell. A story about errors and logs.

And it all started when I noticed the disk space on our server was gradually decreasing.

So today I logged onto our API server (Ubuntu running Apache/PHP) and did a df -h to check the disk space, and was surprised to see that it had noticeably decreased since the last time I'd checked when everything was running smoothly. But seeing as this server does not store any persistent customer data (we have a separate db server) and purely hosts the stateless API, it should NOT be consuming disk space over time at all.

The only thing I could think of was the logs, but the logs were very quiet, just the odd benign message that was fully expected. Just to be sure I did an ls -Sh to check the size of the logs, and while some of them were a little big, nothing over a few megs. Nothing to account for gigabytes of disk space gradually disappearing.

What could it be? I wondered.

cd ../..
du . | sort --sort=numeric

What's this? 2671132 K in some log folder buried in the api source code? I cd into it and it turns out there are separate PHP log files in there, split up by customer, so that each customer of ours (we have 120) has their own respective error log! (Why??)

Armed with this newfound piece of (still rather unbelievable) evidence I perform a mad scramble to search the codebase for where this extra logging is happening and sure enough I find a custom PHP error handler that is capturing (most) errors and redirecting them to these individualized log files.

Conveniently enough, not ALL errors were being absorbed though, so I still knew the main error_log was working (and any time I explicitly error_logged it would go there, so I was none the wiser that this other error-catching was even happening).

Needless to say I removed the code as quickly as I found it, tail -f'd the error_log and to my dismay it was being absolutely flooded with syntax errors, runtime PHP exceptions, warnings galore, and all sorts of other things.

My jaw almost hit the floor. I've been with this company for 6 months and had no idea these errors were even happening!

The sad thing was how easy to fix all the errors ended up being. Most of them were "undefined index" errors that could have been completely avoided with a simple isset() check, but instead ended up throwing an exception, nullifying any code that came after it.

Anyway kids, the moral of the story is don't split up your log files. It makes absolutely no sense and can end up obscuring easily fixable bugs for half a year or more!

Happy coding.

  • 4
    The API codebase was probably in /opt or /usr. Or maybe, total amateur hour, in /home. I'm not 100% against splitting logs, but god damn it, they go in /var if they go anyfuckingwhere.
  • 1
    Or don't use log files, log to bugsnag/sentry/rollbar.

    A webserver should be automatically deployed from git, and you should be able to rapidly create & destroy webservers. So the server should contain nothing permanent.
  • 0
    "separate PHP log files in there, split up by customer, so that each customer of ours (we have 120) has their own respective error log! (Why??)"

    ...are you kidding me? that's actually an amazing idea, no more filtering through global logs to find out what fucked up for the specific customer, now, instead, I can see all of his actions linearly! that's kinda great!
  • 1
    "Conveniently enough, not ALL errors were being absorbed though, so I still knew the main error_log was working"

    ...CAREFUL, there's a difference between an error, and an exception, in PHP...!

    "but instead ended up throwing an exception"

    ...yeah... just as I said...
  • 1
    @Midnigh-shcode I think a better idea would be to simply tag each error message with an identifier you could filter by.

    But presumably that's the reason he did it, so that if a specific customer was having problems their log could be analyzed and the error figured out, but the problem is noticing the errors in the first place. I'd rather have everything go to a single log file that I can keep my eye on instead of trying to manage 100 or so separate log files.
  • 1
    @devios1 it's php.
    regardless how you do error logging, there will always be a problem noticing errors.
    php itself has problem noticing its errors, and it's an intended feature
Add Comment