Using SQL date_trunc to group log records for troubleshooting

Did you ever notice a recurring error message in your log files, only to wonder if the problem has recently become more severe, or has actually been happening -- unnoticed -- for quite a while? If your log data is in SQL format, or any format you can query using SQL, a good technique is to group the records by time period to see if the error has become more prevalent over time.

Here's a real-world example. In a SQL table named log, which includes columns named timestamp (the time the record was written) and message (text giving details of what was logged), I stumbled across many records where message  had the value 'ConnectionError in application_cache'. I wanted to learn whether this error had suddenly become more frequent. This query gave me the answer:

select date_trunc('day', timestamp) as d, count(*) from log where message = 'ConnectionError in application_cache' group by d order by d

The date_trunc function takes a timestamp and "rounds it down" to the nearest specified unit -- the nearest day in my example. Instead of 'day', you can specify any unit from 'microseconds' all the way up to 'millennium'.

The results of my query, a count of the number of matching messages per day, looked like this:

That told me what I needed to know: This message happens many times per day, and the frequency hasn't increased recently.

My database is PostgreSQL 9.x, and the PostgreSQL date_trunc function is documented here. Whichever SQL database your using, a similar function is likely available, and may come in very handy.

Using old commits in GitHub to troubleshoot -- and fixing a common SQL error

By this morning, evidence was mounting that something was wrong -- very wrong. Support reps were reporting that customers' files weren't getting processed promptly. They had already mentioned a few days ago that some video clips uploaded by customers weren't appearing when expected. And this morning, our real-time dashboard showed that no video files had been uploaded in the last 24 hours, when this number is typically in the hundreds.

I realized that all the affected features had something in common: they depend on a scheduled job that processes CSV files for every customer several times per day. A check of audit logs revealed that this job was writing more than 10,000 log messages per day through Aug 11, but fewer than 200 per day starting on Aug 12. Clearly, something was not right with the scheduling!

Our software engineers note all deployments in a Slack channel, which showed we did a deployment on Aug 11. But how to figure out exactly how and where the problem was introduced? That's where GitHub's ability to compare commits came in handy. Here's how I used it:

1. Log in to GitHub, navigate to the repo, and click commits.

2. Page through the commits until one with a date shortly before the suspect deployment is found. I chose one from 5 days ago.

3. Copy the commit hash. Then use GitHub's compare route to compare that commit to master. This route requires two commit hashes or branch names, separated by three dots, e.g. https://github.com/<my account name>/<my repo name>/compare/23948e9f51d0b6c248193e450df0a7e2c3077037...master.

4. Click Files changed.

Now it's just a matter of scrolling through the diff to see which changes might be relevant to the problem. In this case, it was easy to spot: a SQLAlchemy query in the module that processes CSV files had been modified. With the problem isolated to a few lines of code, it was easy for me to figure out what I had done wrong when changing the query.

It turns out that, when I added a new condition to a SQL query, I made a common mistake. A comparison of any value to null is always false. That's true even if the comparison uses the not equals operator! So this query:
select count(*) from config
where ftp_format_ex != 'add_photo_urls_to_inbound_feed'

was finding only 370 rows -- the ones where ftp_format_ex not only was not equal to 'add_photo_urls_to_inbound_feed', but was also not null.

This mistake is so easy to make that I also made it back in 2014, and blogged about it then!

The null-coalescing operator -- in this case, converting nulls to the empty string -- gives the result I really wanted:
select count(*) from config
where coalesce(ftp_format_ex, '') != 'add_photo_urls_to_inbound_feed'

The above query finds 3,528 rows. In the module identified in GitHub, adding coalesce to the query caused all the expected CSV files to be processed and solved the problem.

The moral of the story? Keep good logs, isolate problems by comparing older commits to the current commit in GitHub, and be careful of nulls in SQL.

Using CloudFront access logs to investigate unexpected traffic

Amazon's content delivery network (CDN), CloudFront, has many benefits when serving web content to a large global audience. A small, but important, one of those benefits is detailed logging, which I recently took advantage of to investigate some unusual web traffic.

It all started with a CloudWatch alarm. I had configured CloudWatch to email me if my CloudFront distribution received more than a specified number of requests per minutes. I received such an email, clicked the link to view the alarm details in the CloudWatch console, and accessed a graph plotting requests per minute against time. Zooming out to a two-week scale, I immediately noticed sharp peaks occurring around 20:00 UTC most days.

How to find out where the excess traffic was coming from? CloudWatch and CloudFront offer a variety of graphs with resolutions as detailed as one minute. And CloudFront offers a report of top referrers, that is, websites from which the most requests to the CloudFront distribution originated. However, the shortest time unit the top referrers report covers is one day, not of much use for identifying the source of a traffic spike lasting only a few minutes.

The answer was to consult the CloudFront access logs, which, when enabled, are stored as text files on Amazon S3. Fortunately, logging was already turned on for my CloudFront distribution. If it's not, you can enable it in the AWS Console by selecting your distribution and clicking Edit on the General tab.

The log files can then be found in the specified bucket and folder in the S3 console. Focusing on the peak that occurred around 20:00 UTC on June 24, I typed in a prefix and sorted by Last modified to zero in on the relevant logs. (Tip: timestamps are in UTC on the CloudWatch graph and in the names of the log files on S3, but the last-modified time in the S3 console is in your local time zone.)

Each log is a zipped (.gz) file. Unzipping it yields a tab-delimited text file, which you can open in a text editor, view in your favorite spreadsheet program, or analyze by writing a script. Here are the first few lines of a typical log file:

Following two header rows, each row represents one request to a URL served from the CloudFront distribution. The relevant fields are time and cs(Referrer). The referrer is the URL of the page from which the event originated. I wrote a Python script to read the log files and output a CSV file with one row per request, where each row consists of the time (truncated to the minute) and the domain name.

It was then simple to sort the CSV file by minute and domain name. In this way, I found the domain that was responsible for the excessive traffic in the minutes shortly after 20:00 UTC on June 24. Armed with this knowledge, I was able to contact the owner of that domain and ask why their website was receiving such heavy use around 20:00 each day. (As of this writing, I'm waiting for their reply.)

If you prefer not to write a script, you might instead take advantage of Amazon Athena. Once you define an appropriate schema, Athena lets you query data on S3 without downloading it or writing code.

Many thanks to the engineers at the AWS Loft in New York for pointing me in the direction of CloudFront access logs. I hope you found this article informative and helpful.

Turning unstructured text into a SQL query

It sounds trivial, but querying a SQL database for records that match data provided in an unstructured format such as a text file can be a challenge. The goal is to construct a SQL query with a possible lengthy in clause, without a lot of manual copying and pasting. Consider this example: a colleague supplies a list of customer names in the body of an email message. (The principle is the same if the list is in a text file, a PDF document, or any similar format.) Something like this:

Hey Steve,
Just got this list of customers from Marketing. Could you look up the date of most recent login for each of them? Of course it's an emergency, has to be done before tomorrow's big conference.
Thanks,
Lenny Lastminute
-------------------------------
Acme Anvils, Inc.
Big Bertha's Balloons, LLC
Crazy Cars & Co
Dynamite Dog Food Enterprises
Excellent Eggs, Inc.

Since the list has only five customers, it wouldn't be hard to copy and paste to come up with a query like this:
select name, last_login_date from customer where name in (
    'Acme Anvils, Inc.',
    'Big Bertha''s Balloons, LLC',
    'Crazy Cars & Co',
    'Dynamite Dog Food Enterprises',
    'Excellent Eggs, Inc.'
) order by name

But now let's imagine that the list has hundreds of entries, and the customer table has millions of rows, so we don't just want to retrieve all of them and manually identify the relevant ones. Fortunately, there are some tricks we can do in LibreOffice Calc (or Excel or your favorite spreadsheet program if you're not a Linux geek).

Start by pasting the list into the first column of a blank spreadsheet:

Now place a formula like this in cell B1:
="select name, last_login_date from customer where name in ('" & A1 & "'"

Yep, those are single-quotes (which SQL requires) inside double quotes (which LibreOffice Calc requires).

And place a formula like this in cell B2:
=B1 & ", '" & A2 & "'"

Copy the formula from cell B2 to all the remaining cells in column B. You'll end up with something like this:

Then we just need to close the parens, and perhaps throw in an order by clause and a semicolon, which we can do with a formula like this below the last cell in column B:
=B5 & ") order by name;"

That cell now contains our SQL query:
select name, last_login_date from customer where name in ('Acme Anvils, Inc.', 'Big Bertha's Balloons, LLC', 'Crazy Cars & Co', 'Dynamite Dog Food Enterprises', 'Excellent Eggs, Inc.') order by name;

But we're not quite done. If you have sharp eyes, you may have noticed the SQL syntax error. One of the customer names, Big Bertha's Balloons, LLC, contains an apostrophe, which is the same as a single quote, which is a reserved character in SQL. We can escape it by doubling it. To automate replacing ' with '', change the formula from =B1 & ", '" & A2 & "'" to:

=B1 & ", '" & SUBSTITUTE(A2, "'", "''") & "'"

This results in a valid SQL query, like so:

select name, last_login_date from customer where name in ('Acme Anvils, Inc.', 'Big Bertha''s Balloons, LLC', 'Crazy Cars & Co', 'Dynamite Dog Food Enterprises', 'Excellent Eggs, Inc.') order by name;

I hope this saves you some time someday!

Installing Numpy on Ubuntu

I needed the numpy module in order to run one of my Python programs. I'm running Python 2.7.6 on Ubuntu 14.04.

I first tried pip install numpy. No luck. After a while, this error was displayed: UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 72: ordinal not in range(128). The installation did not complete successfully.

Then I tried sudo apt-get install python-numpy. That did the trick. A tip of the hat to my colleague Collin Stocks for this advice.

A uWSGI Bug: A (Partial) Success Story About Logging and Testing

Users of SpinCar's mobile app recently started mentioning that they were seeing an error message. Not every user was affected, but it happened to enough users that it was clearly not an isolated problem. The error message was far from specific, indicating that something unexpected went wrong without giving any details.

The first place we looked to isolate the problem was MixPanel. We use this service to log events that occur in the app, including nonfatal errors. (We also use Fabric.io's Crashlytics, but that tends to be more useful for fatal errors that actually crash the app.) Fortunately, MixPanel did reveal details about at least one occurrence of the error. We could see that the app had made a particular call to the our back-end API, and that the API responded with an HTTP status of 502 (bad gateway). Furthermore, the full details of the offending HTTP request had been logged.

Our good luck in continued when we tried to replicate the problem. Simply by making the same HTTP request in a web browser, we provoked the same 502 response, using the production copy of the API. The next question was: Could we do so in the development environment, where we'd be able to troubleshoot and test potential fixes? The answer was yes! Running a local copy of the API and sending it the same request once again led to the 502 response.

In the development environment, we were able to see a detailed error message mentioning "invalid request block size." A Google search revealed that uwsgi, which use to serve our API, limits the size of requests, and the default maximum is 4,096 bytes. We corrected the problem by launching uwsgi with the buffer-size parameter to set a larger maximum. The bug was resolved within a few hours of the initial report, with no need to submit a new version of the iOS app for Apple's approval.

That's a success story, and the success was driven largely by two factors. First, adequate logging enabled us to get details about the error, even though the message displayed to users was uninformative, and the users themselves were non-technical customer personnel at distant locations. Second, the development environment closely mimics the production environment. In this case, it was a critical factor that uwsgi was used -- and used with the same settings -- in dev as well as on prod.

But, of course, the success is only partial. Real success would be avoiding the bug in the first place. How did this error slip through the cracks despite the fact that our app and API undergo extensive code review and automated testing? The answer is that the bug only occurs with very large requests, which only occur when users have used the app to create a great many videos -- far more than are created in our automated tests. This bug could have been revealed by the type of testing known as load testing or stress testing, in which actions are performed repeatedly and large data sets are used. There are a couple of reasons we haven't implemented this type of testing yet. One is that the open-source automated testing tools we rely on tend to crash during long test runs. But the main reason is that we haven't yet found the time to develop load tests. It's definitely on the to-do list!

Amazon LightSail

Amazon Web Services recently announced LightSail, a low-cost service for quickly launching a virtual server with limited options. Fewer steps and less technical knowledge are required to get a simple website up and running than with traditional AWS services like EC2. LightSail seems intended to compete with low-cost virtual hosting services such as GoDaddy's.

Upon selecting LightSail from the AWS management console, it opens in a new tab with its own subdomain, lightsail.aws.amazon.com. This isn't true of most other AWS services, and may imply that Amazon views LightSail in a separate category.

At work, where scalability and reliability are key, I have no plans to use LightSail. However, I did have a chance to put it to the test for a personal project, a new website for my band, The Showoffs. Users with no technology background might not find it easy to get started with LightSail. But if you're familiar with the basics of DNS and virtual hosting, LightSail offers a quick and affordable setup. In about an hour, I went from nothing -- no domain registered, no server, and no content -- to a functioning WordPress site.

Amazon provides documentation here. For my project, the articles on getting started, static IP addresses, and using WordPress with LightSail were particularly relevant. (On the other hand, this DNS article led me astray. It turned out not to be pertinent; all I had to do was create an A record in Route 53.)

The main steps to create theshowoffsband.com were as follows:

• In Route53, registered the domain name. This required replying to a verification email.
• In LightSail:
• Created an instance. I chose the WordPress 4.6.1 instance image and the $5/month instance plan.
• Created a static IP address.
• Created a DNS zone, but I think this step was unnecessary.
• Connected to the server using SSH. A button in the LightSail opens a browser-based SSH connection with a singe click (screenshot below).
• Obtained the WordPress credentials by running an Amazon-provided script.
• Returned to Route53 and created an A record mapping theshowoffsband.com to the static IP address. I then waited several minutes for the DNS record to propagate.
• Visited my new website's WordPress admin page, logged in, and started adding content.

The cost? $12 per year for the domain registration, and $5 per month for the virtual server. If you show up at the Showoffs' next gig, it will have been worth it!

SSH connection to the LightSail virtual server with a single click