How We Tracked Down an Exception Without Errors: A Detective Story

Tom de Bruijn

Tom de Bruijn on

How We Tracked Down an Exception Without Errors: A Detective Story

This is a short detective story about how we tracked down an exception in's flow that didn't cause an error...

The Impossible Could Not Have Happened

It all started with a support request. A strange support request. A user reported to us that they didn't have access to an organization after accepting an invitation to the organization.

Looking at the organization in our admin panel, we could see that the user was part of this organization. So they should have been able to see the organization's app on signing in. But the impossible could not have happened, therefore the impossible must be possible in spite of appearances, as Hercule Poirot would have said. And indeed, upon closer inspection, we realized that while the organization listed the user as a member, from the user's perspective in the database, they were not part of the organization.

1> user = User.find("user_id_2")
2> user.organization_ids
3# => []
5> organization = Organization.find_by(:slug => "toms-test-apps")
6> organization.user_ids
7# => ["user_id_1", "user_id_2"]

The User <=> Organization association is a 'has and belongs to many' association managed by Mongoid ORM in our MongoDB database.

Something had gone terribly wrong with the associations. Users were only getting linked from one end of the association and not the other. As we do with such reports, we start looking at our private AppSignal instance that monitors to see what could have gone wrong. But unfortunately, we didn't find any errors that could tell us more.

This meant that we had to do some old fashioned detective work. We grabbed our magnifying glasses and dove headfirst into the code—using order and method, and the little grey cells.

We have a central location where the invitation accepting logic is located, but multiple actions from where it is called. These actions are: when signing up, when signing in, and clicking the accept invitation link while signed in.

For context, our invitation accepting logic lives in a shared module used by certain controllers. The module exposes an accept_open_invitations method called from the different flows that allow accepting invitations.

1# app/controllers/concerns/invitations.rb
2module Concerns::Invitations
3  def accept_open_invitations
4    # Invitation id set by the InvitationsController when a user is not signed
5    # in or decides to accept it under a different user account.
6    invitation_id = session[:invitation_id]
7    return unless invitation_id
8    invitation = Invitation.find(invitation_id)
9    invitation.accept_for_user(current_user)
10  end
13# app/controllers/users/sessions_controller.rb
14class Users::SessionsController
15  include Concerns::Invitations
16  def create
17    # Do sign in logic...
19    # After sign _in_, do this custom action
20    accept_open_invitations
21  end
24# app/controllers/users/registrations_controller.rb
25class Users::RegistrationsController
26  include Concerns::Invitations
27  def create
28    # Do sign up logic...
30    # After sign _up_, do this custom action
31    accept_open_invitations
32  end

In the Dark

Even though we figured the problem must have come from one of the sign in/up scenarios, we couldn't figure out which one it was. The code for accepting invitations was working perfectly fine in our automated and manual tests. So was there something else happening in the controllers after the invitations were accepted? Perhaps an incomplete in-memory state that was persisted to the database after the invitation was accepted, thus undoing the invitation?

Without a reproducible state, we had no idea where the problem could be. How were we going to find the cause of the problem in production? What was causing the perfect storm where accepting invitations only half accepted them?

Since there was no error being raised, we couldn't see the details in AppSignal. Yet. We knew how to detect the problematic association state, so we started tracking them after invitations had been accepted, by reporting an error where previously there was none. This allowed us to use AppSignal's error reporting system using a custom error that we created without raising the error and breaking the flow for users. It all happens silently in the background.

1# app/controllers/concerns/invitations.rb
2module Concerns::Invitations
3  def self.included(base)
4    # Call this method for every controller this concern is included in
5    # after performing an action/request.
6    base.after_action :perform_user_organization_association_check
7  end
9  def accept_open_invitations
10    # Invitation id set by the InvitationsController when a user is not signed
11    # in or decides to accept it under a different user account.
12    invitation_id = session[:invitation_id]
13    return unless invitation_id
14    @perform_user_organization_association_check = true
15    invitation = Invitation.find(invitation_id)
16    invitation.accept_for_user(current_user)
17  end
19  def perform_user_organization_association_check
20    # Only perform the check if there was an invitation accepted during
21    # this request.
22    return unless @perform_user_organization_association_check
24    organization_ids = Organization.where( => []).pluck(:id)
25    user_organization_ids = current_user.organization_ids
26    # The associations match, do not report this as an error
27    return if user_organization_ids.length == organization_ids.length
29    # Add an error to this request that's being tracked by AppSignal.
30    # This makes sure we have all the environment details for this request,
31    # along with this custom error report.
32    Appsignal.set_error(
33      <<~ERROR
34        Mismatch in user <=> organization associations.
35        database: #{organization_ids.sort}
36        controller: #{user_organization_ids.sort}
37      ERROR
38    ))
39  end
42# Custom error class so we can track them in AppSignal easier
43class InvalidUserAccountAssociationError < StandardError; end

The important part in this code example is the Appsignal.set_error method call that tracks a custom error for this request without it reraising and showing an error page to the user. You can use this yourself as well, see the documentation.

Chasing the Culprit

We deployed this custom error tracking code and sure enough, the errors started trickling in as people were accepting invitations. After fixing some false positives, we finally had errors being reported that matched the incorrect state of user and organization associations in the database. They were all happening during the sign up flow of new users while accepting an invitation.

Screenshot of the AppSignal incident detail page for this custom error

Screenshot of the AppSignal incident detail page for this custom error

So now we had samples of errors with a lot of details that could cause the problem. Now the real detective work started. What of these many details (e.g. request params, session data, tags, etc.) was causing the problem?

It took a couple of failed invitations for us to spot something odd in the request parameters: "accepted_terms": "0",

2  "action": "create",
3  "controller": "users/registrations",
4  "user": {
5    "accepted_terms": "0",
6    "email": "[REDACTED]",
7    "name": "Tom",
8    "password": "[FILTERED]"
9  },
10  # ...

During sign up, users need to accept the AppSignal Terms & Conditions before they can use AppSignal. When they do not, the sign up fails and they need to resubmit the form after accepting the Terms & Conditions.

It struck us as odd that this could be causing the problem since we test for an incorrectly filled in sign up form. But we went ahead and tried reproducing the scenario anyway. Sure enough, the following popped up when I tried to accept an invitation without accepting the Terms & Conditions.

Screenshot of the sign up page showing a message that the invitation was accepted but the Terms & Conditions are not accepted

Screenshot of the sign up page showing a message that the invitation was accepted but the Terms & Conditions are not accepted.

Elementary, My Dear

This faulty state was just what we were looking for. If users continued to sign up, accepting the Terms & Conditions, they would end up in the faulty association state between users and organizations. Turns out, that while we test the form to be filled in incorrectly, we didn't test if the Terms & Conditions weren't accepted...

We quickly added another test case, and now that we had found the culprit, we fixed the issue. Thank you Robert for helping me find this exception without error! Relieved, we deployed the fix the next day. Now it should no longer happen.

To ensure that it doesn't, we've kept the reporting logic in the controllers for now so that we can keep an eye on it if it happens again. When we're confident that we've fixed the issue, we'll remove the error reporting code and it will be business as usual again.

🎬 So ends the story of the exception that didn't raise an error. With the culprit safely eliminated.

PS: If you liked this detective story featuring AppSignal, you might also like this story, or write your own story of solving crimes in code helped by an APM like AppSignal.

Share this article

Tom de Bruijn

Tom de Bruijn

Tom is a developer at AppSignal, organizer, and writer from Amsterdam, The Netherlands.

All articles by Tom de Bruijn

AppSignal monitors your apps

AppSignal provides insights for Ruby, Rails, Elixir, Phoenix, Node.js, Express and many other frameworks and libraries. We are located in beautiful Amsterdam. We love stroopwafels. If you do too, let us know. We might send you some!

Discover AppSignal
AppSignal monitors your apps