2016.05.29 00:00 | Kurt Tomlinson
I wrote the BarStack Windows App way back in 2014 when Windows 8 was brand new. Windows 8.1 hadn't been released yet, and "Metro" style apps had just been rebranded as "Windows Store" apps. Developing Windows Store apps was major pain. The development tools didn't work very well, and the GUI building blocks were far from refined.
Since then, a lot of time has passed. I moved on from BarStack and created my blogging platform, Bloopist. The last update I made to the BarStack Windows app was probably in late 2014, and the majority of updates I made to the BarStack website were security-related. Any new features planned for BarStack were put on hold.
Recently, I was notified that the BarStack Windows app wasn't working. I fired it up to check it out, and it definitely wasn't. It crashed right away when it tried to log in. The first couple bugs were pretty easy to find. The server was responding with text instead of JSON data, so that caused the JSON parser in the Windows app to throw an unhandled exception. I corrected this on the server side, so the Windows app now longer crashed on startup.
The next bug was much harder to root-cause. When the app tried to log in to the server, the server would respond with a JSON structure with an empty "email" field and a null "password" field. According the BarStack API documentation I had written a few years ago, the response was supposed to include a "success" boolean, a "auth_token" string, and an "email" string.
After several hours of poking around, I finally noticed that my Ruby on Rails server process was processing GET requests from the Windows app when in production mode and POST requests when it was in development mode. There was something wrong in production that wasn't wrong in development. The Rails code was properly interpreting a GET to the sign-in path as an "index" action, but the Windows app should have been making POST requests that would be interpreted as "create" actions for the Rails server's sessions controller.
For some reason, POST requests were being turned into GET requests in my production environment before they were handed off to my Rails app's controllers. I checked my webserver's NGINX access logs to see what was going on. I saw that whenever the BarStack Windows app was making a POST requested, NGINX was responding with a 301 Moved Permanently redirect followed by the BarStack Windows app making a GET request for the same resource. I did some digging and found that NGINX could be redirecting the BarStack Windows app because of a rewrite rule. After a redirect, only GET requests can be made. NGINX wasn't the culprit, but this information did help me find the real problem.
After a couple hours of trying to get NGINX to log its redirects and confess to a crime that it didn't really commit, I moved down the stack a little bit. In the BarStack web app, NGINX hands off requests to the Rails app, and then the Rails app processes those requests with Rack before handing it off to the Rails app's controllers. In my Rails app's logs, the first POST request was never recorded, and NGINX wasn't responsible for sending the redirect response. That meant that somewhere in the Rack Middleware portion of the BarStack web app, a redirect response was being generated.
I opened up the gemfile for the BarStack web app and took a quick look around. In the middle of the file, I saw
gem 'rack-ssl', :require => 'rack/ssl' #enable https connections
Oh yeah! I had forgotten that I had started forcing people onto secure https connections. (The purpose of the rack-ssl gem is obvious when you consider its description on rubygems.org is "Rack middleware to force SSL/TLS.") Any connection that was made over http would get redirected to the same resource but with https, and my Rails app's controllers would never know about the original request! That expains why I saw a POST and a GET in my NGINX access logs but only a single GET in my Rails production logs.
I checked the BarStack Windows app's API endpoint, and sure enough, it started with http://.... I slapped an "s" into the endpoint constant, recompiled the app, and it ran smooth as silk.
And that's the story of how I fixed a bug with a single keystroke after 8 hours of debugging.
Photo by Forsaken Fotos