Talks
Debugging Adventures in Rack-land
Summarized using AI
Debugging Adventures in Rack-land
by Pan ThomakosThe video titled "Debugging adventures in Rack-land" features speaker Pan Thomakos, who shares his experience with a bug in a Ruby on Rails application related to display preferences. The presentation is part of the EuRuKo 2018 event, focusing on the intricacies of debugging within the Rack framework, a minimal interface for web applications in Ruby.
Key points of the presentation include:
- Introduction to the Bug: Thomakos describes a "double refresh bug" encountered when users change their display preferences (from metric to imperial units) in an app. After saving preferences, refreshing the page wrongly resets the values, leading to confusion.
- Initial Investigation: He confirms the bug is not related to database persistence, as values are saved correctly. He uses tools like Pry for debugging, enabling interactive console access during the method’s execution.
- Exploring Rack Middleware: Thomakos delves into Rack’s functionality, emphasizing how it processes HTTP requests. He discusses how caching mechanisms, particularly through the entity map, can lead to stale data displayed after requests.
- Middleware and Caching: The reasoning behind the unexpected behavior of the application relates to how Rack’s middleware operates, particularly with the entity map cache that retains values through sessions. Clearing this cache appropriately during web requests is critical for accurate data handling.
- Creating Custom Middleware: He outlines a custom middleware example that tracks request durations, demonstrating how to achieve this correctly without affecting response accuracy.
- Identifying the Root Cause: Ultimately, Thomakos traces the problem back to an e-tag middleware which failed to invoke necessary closure calls for other middlewares, highlighting the importance of lifecycle management in middleware.
- Conclusions: He expresses the value of understanding how minor adjustments in the coding and middleware can lead to significant improvements in application performance and user experience.
In conclusion, Thomakos’s talk showcases a real-world debugging scenario in a Ruby on Rails application, offering insights on Rack middleware’s role and how attention to detail within request lifecycle management can enhance system integrity. It serves as a practical exploration into the world of Ruby development and debugging frameworks.
00:00:00.030
Let's get started a bit early so that we know you are all here. Please gather at the front so we can swiftly do the switcheroo.
00:00:06.240
This is a reminder for everyone who has coached or organized the Rails Girls workshop before; please join me in the front during the break for a photo.
00:00:12.889
Now, I'm excited to introduce our next speaker, Pan Thomakos. Pan leads the productivity engineering team for Ruby on Rails and the JavaScript platform. He loves developing automation to reduce manual tasks.
00:00:25.320
Recently, he encountered a rather weird bug while trying to solve an issue, which led him into the depths of Rack. So, without further ado, let's give a warm welcome to Pan!
00:00:40.860
Thank you! I’m excited to share a little bit about this adventure I went on, and through that, I hope to help you learn about Rack just as I did along the way. For those of you sitting in the back who can’t see me well, I look like this, but my beard is a little longer than in this picture, and I’m not wearing a button-down shirt.
00:01:04.780
I work for a company called Strava, which is a social network and training log site for athletes. Basically, you might go on a run or a bike ride, upload a bunch of GPS and power meter data, as well as heart rate data. We allow you to delve into that data to uncover cool insights about yourself and compare them with your friends and past performances.
00:01:23.710
Today, I want to discuss a double refresh bug that I encountered in our Rails application, which I refer to as the "double refresh bug." Let me explain why. In our application, there's a screen that enables you to change your display preferences. For instance, as an athlete in Europe, you might want to see metrics in kilometers and kilograms. Meanwhile, if you live in the United States, you'd want to see those in miles and pounds.
00:01:49.660
So, here's how this bug works: I go to a drop-down menu and select "miles" and "pounds" instead of the default "kilometers" and "kilograms." After clicking save, there's an AJAX action that hits the server to persist that preference. However, when I refresh the page, the value flips back to kilometers and kilograms. After refreshing again - hence the "double refresh" - it finally updates to miles and pounds.
00:02:28.420
At this point, my initial reaction was to determine if this issue was impacting the database. Am I persisting the correct value, or is it simply a code issue? I needed to narrow down the possibilities.
00:02:40.299
I wrote a query to hit the database, and luckily, it confirmed that the value is actually being persisted correctly. This action gave me some insight that I needed to investigate further. Our settings controller handles all these display preference views, containing an athlete method. This method takes the current athlete since you're only allowed to modify your own preferences and wraps it with a permissions decorator.
00:03:15.500
It's not vital, but it exposes that athlete to all the controller methods. So, I dug into my debugging toolbox and pulled out Pry. For those unfamiliar, Pry is like IRB but comes with numerous cool additional features.
00:03:28.370
One of my favorite features is that it allows you to invoke Pry on a Ruby binding object, acting as a breakpoint to interactively engage with the code.
00:03:33.620
I inserted a binding.pry call into my athlete method, refreshed the page, and suddenly I was in an interactive console. This console informed me of precisely which file I was in and the specific line of code running. Moreover, it provided a neat visual representation of where I was in that method.
00:03:56.120
Excitedly, I asked, "What is the measurement preference for the current athlete?" and it responded with "meters," which was incorrect since I was trying to switch to feet. I thought, let's use Active Record instead and query the database directly using the same athlete ID to see its value. Interestingly, it returned "feet." This discrepancy was puzzling.
00:04:29.330
To investigate further, I looked at the method definition for the current athlete, which employs a find method from the application controller. There are two ways to log in: through a remember cookie, which is a long-lived session, or through the current session cookie.
00:05:08.750
I confirmed I was using the current session since I was actively engaging with the website. Diving deeper into this method revealed additional code, but the key point is that I'm using the session ID to determine my athlete ID.
00:05:21.770
Next, I thought it would be apt to explore how the athlete.fetch behaves. Unfortunately, when I did this, I still received "meters," indicating it was the same as the current athlete's value.
00:05:39.949
Thus, I needed to analyze the method definition for fetch. The fetch method has a simple API: it takes an ID like the find method and hands off to this entity map.
00:06:07.620
As it turns out, the entity map is a request-level cache that saves time when requesting an object by its primary key, allowing you to skip hitting the database.
00:06:31.369
This approach means you don't need to go back to the database if that object is already cached in memory. When you issue requests, the method generates a cache if one doesn’t exist and retrieves requested primary keys.
00:06:43.879
However, when I tried fetching a preferred value again, I still got the incorrect meter value. When I cleared the cache and requested it again, I finally got the correct value.
00:07:11.929
Having established this, I pondered: how do I clear this cache during web requests? I immediately thought about Rack middleware, knowing each request requires a fresh cache.
00:07:31.459
For those unaware, Rack serves as a minimal interface between web or application servers and your Ruby application that communicates via HTTP.
00:07:53.290
You might have web servers like Puma or Unicorn on one end and Ruby frameworks like Rails, Hanami, or Sinatra on the other, all speaking Rack and thus interchangeable.
00:08:12.070
So what does Rack need to generate an HTTP response? Essentially, we need a status code, headers indicating the content type, and the actual response body.
00:08:43.310
A Rack response is represented as an array containing three main elements: the status, the headers (a hash), and the body (the actual content such as JSON or HTML).
00:09:09.230
However, the Rack API allows me to send back multiple bodies as an enumerable. This can be useful for buffering and streaming, so while I generate the response, I can send preliminary parts to the browser.
00:09:34.320
Middleware is where it gets interesting. Rack handlers talk to servers while your Ruby application, on the other end, does its length according to the middleware.
00:10:35.069
You'll understand soon that timing management in middleware can leach a lot of resources in real-time configurations. Let's create a sample middleware to keep track of requests.
00:10:50.100
After processing the response through the middleware stack, I can measure CPU time. Here's an example of a 'Timer' middleware to measure request durations.
00:11:11.220
I'll track the time at the beginning and return the original response at the end. However, there's the catch that the middleware handler iterates after returning, which might not reflect accurate timings for slower responses.
00:11:30.420
So how do we know when our response is truly complete? Rack provides the 'close' method: when the request has gone through the entire response pipeline, it can call close, ensuring completion of all tasks.
00:11:44.430
To adjust my middleware to accommodate this, I create a body proxy. The proxy wraps the original body and runs additional code when it closes, allowing me to account for various lifecycle events in the middleware.
00:12:05.170
This is an effective technique for separating calling concerns. The body can handle the response tasks, while the close method manages the closure aspect rightly.
00:12:25.050
In this middleware system, we can leverage Rack's body proxy. By returning original status and headers alongside my new proxy body, I account for all processes.
00:12:45.110
Now, I managed to fix timing issues successfully by updating how I tag my middleware. After testing, I can determine where the hanging issue lies.
00:13:02.660
I ran into this peculiar display preferences problem; oddly, I have to refresh the page twice to get the accurate response from the database. After pinpointing the issue to the entity map...
00:13:36.850
...I learned that we cleared our entity cache when migrating from Rails 3 to Rails 4 and transferred functionality to the entity map.
00:13:50.830
Before it cleared, we had a middleware piece that cleared that entity map at the end of the request cycle - this behavior is essential for accurate data interpretation.
00:14:09.100
When I added in my 'bind pry' calls to observe close calls, I refreshed and found my console, reassuring myself about middleware interactions.
00:14:31.650
As I scrutinize my requests, I map out proxies, but I realize my entity map middleware proxy does not exist in the expected places.
00:14:45.220
After validation, I reviewed the sequence: where's my entity map, and what happens in different HTTP requests? Once identified, I noticed the middleware flow.
00:15:01.999
Now, I hypothesize a connection between an unwanted middleware layer reforming requests and returning responses lacking a proper pipeline closure.
00:15:23.160
After rigorous debugging, I discover the root cause to stem from an unexpected caching mechanism inside the e-tag middleware.
00:15:48.599
The conditional handle did not enact closure calls to the subsequent middlewares, demonstrating how core functionality can falter.
00:16:02.440
After addressing the flaw, it became clear the patch was essential for synchronous execution. By directly addressing these lifecycle prompts, we can better inform prospective middleware.
00:16:16.859
In the aftermath, I think of restoring the coding guidelines; maintaining clean integrity in middleware tracking is vital for all workflows.
00:16:41.150
If you're wondering how to enhance the Rack API, I propose adjustments: clarifications around lifecycle management offer better user insights.
00:16:57.329
Upon close confronted by the concern about user programming errors, we can rethink descriptive programming practices or offer insightful automation on our execution responses.
00:17:18.650
Summarizing this adventure: we faced a dubbing bug, improved middleware coherence, and encountered reducing latency in associated requests.
00:17:39.300
Although we resolved our original double-refresh issue, the overall experience taught me invaluable lessons concerning request lifecycle nuance and middleware coordination.
00:18:01.329
In summary, whilst addressing the code dependencies, we now have better implementations ensuring integrity with the additional edge case coverage.
00:18:20.580
I'm appreciative of these explorations into the workings of Rack and how minor adjustments can streamline complex request-response behaviors.
00:18:43.230
Thank you, everyone, for being here today! I'm Pan Thomakos, and I hope this talk inspired you in some way as well!
00:19:10.330
If you are a lightning talk speaker, please come to the front as we prepare for the next session.
Explore all talks recorded at EuRuKo 2018
+8