Debugging Transaction Issues In MariaDB

Transactions are great until they aren’t. I was reminded of this the past couple of days while trying to figure out why some code I was refactoring was all of a sudden timing out.

The Problem

At Husmus, I’ve been on a crusade to simplify some parts of our architecture by getting rid of some low value services in favor of a well structured monolith. One advantage of this is that DB changes that previously could not be in a transaction now can be because all the work can be done with one connection.

This time though, I started seeing strange timeouts. The action would succeed the first time, but fail every time after that.

The Hunch

My immediate hunch was that it was something transaction related. The problem with my hunch though was that I didn’t have a clue how to debug transaction issues with MariaDB. That meant it was time to start digging.

The first command I found to try was SHOW ENGINE INNODB STATUS. This gave me a lot of information, but the relevant part for me was this.

---TRANSACTION 151056, ACTIVE 15 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 2
MariaDB thread id 2081, OS thread handle 139636657866496, query id 109252 172.18.0.1 dotnet_user Update
INSERT INTO Activation (`AccountId`, `Token`) VALUES (175, 'qnAqVdp7')
Trx read view will not see trx with id >= 151056, sees < 151049
------- TRX HAS BEEN WAITING 13265145 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 568 page no 3 n bits 8 index PRIMARY of table `hus`.`Activation` trx id 151056 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 0000000000000001; asc         ;;

------------------
---TRANSACTION (0x7effc0ebca30), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7effc0ebb930), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION (0x7effc0eba830), not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 151049, ACTIVE 95 sec
2 lock struct(s), heap size 1128, 5 row lock(s), undo log entries 1
MariaDB thread id 2077, OS thread handle 139636908463872, query id 109010 172.18.0.1 dotnet_user

The first section showed that a transaction with ID 151056 was waiting to get a lock. Then at the bottom I saw that transaction 151049 had been been active for 95 seconds and was locking some resources. This was a huge red flag that I was on the right track.

The Deep Dive

I had confirmed that it was some sort of transaction issue, but the code I was working on looked fine. It was time to dig deeper. I needed to figure out how to see details of each transaction and each query.

After some digging, I learned about information_schema.innodb_trx. This table shows details about every current transaction. I was consistently able to reproduce the issue and every time I would see one transaction just waiting and locking resources that matched what SHOW ENGINE INNODB STATUS was showing.

From there, I wanted to see what queries were executing in that transaction. First, I had to turn on query logging by running

SET GLOBAL general_log=1;
SET GLOBAL log_output='TABLE';

SELECT * FROM mysql.general_log ORDER BY event_time DESC LIMIT 200

Combined with information_schema.innodb_trx, this unlocked all of the mysteries for me. The value of TRX_MYSQL_THREAD_ID maps directly to THREAD_ID in mysql.general_log. Now I could get a list of all queries executed as part of the hanging transaction.

-- Get all queries executed by the thread with the
-- uncommitted transaction
SELECT event_time, command_type, argument
FROM mysql.general_log
WHERE thread_id = 183 -- The thread id from information_schema.innodb_trx
ORDER BY event_time

This gave the following truncated results.

event_time             |command_type|argument            |
-----------------------+------------+--------------------+
2022-06-07 17:18:44.163|Connect     |dotnet_user@172.1...|
2022-06-07 17:18:44.163|Query       |SET NAMES utf8mb4   |
2022-06-07 17:18:44.167|Query       |SELECT * FROM Que...|
2022-06-07 17:18:45.250|Query       |SET NAMES utf8mb4   |
2022-06-07 17:18:45.251|Query       |set session trans...|
2022-06-07 17:18:45.251|Query       |start transaction   |
2022-06-07 17:18:45.253|Query       |UPDATE Activation...|

The important bits are the last two lines. We see that a transaction was started and an UPDATE executed. Where is the transaction commit though? This was the final clue I needed. I was able to go back to my code and quickly find the transaction that was not being committed. Turns out that this particular bug already existed. It was just my refactoring that exposed it by more efficiently using transactions elsewhere.

Conclusion

This was one of those bugs where I was ready to throw in the towel. This was supposed to be a quick restructuring of some existing code to make it easier to extend in our next project. The imposter syndrome started to hit pretty hard as I was struggling to figure out how to debug this. Multiple times I was ready to just push the branch off to the side for another day.

I’m glad I stuck with it though. Leveling up my MariaDB skills is important. My days of being a DB wizard are years in my past now and mostly on SQL Server. Demystifying this type of debugging in MariaDB will hopefully pay dividends in the future.

Combining the Default Policy in ASP.NET Core

Over the course of my career it seems that every ASP.NET (Core or otherwise) project I’ve inherited ignores the built-in policy-based authorization support. The codebase I inherited at Husmus is no exception. But this time I have the power to fix it!

"Fix all the things" meme

Policy-based authorization allows you to define a default policy. This policy will be applied to any endpoint that has the [Authorize] attribute, but no explicit policy.

public void ConfigureServices(IServiceCollection services)
{
    ...

    services.AddAuthorization(options =>
    {
        options.DefaultPolicy = new AuthorizationPolicyBuilder()
            .RequireClaim("AccountActivated")
            .Build();
    });

    ...
}

For example, the default policy will be applied to Index, but not to New.

// Uses the default policy
[Authorize]
public IActionResult Index()
{
    return Ok();
}

// Only users who satisfy this policy
// are authorized. The default policy
// is not applied.
[Authorize("CanCreateWidget")]
public IActionResult New()
{
    return Ok();
}

That’s not what we want here though. We want CanCreateWidget and the default policy to both be applied. We want to build on top of the default policy so that the user is required to have activated their account and be able to create a widget. One ugly way around this is to add multiple [Authorize] attributes. The framework will treat these as a logical AND, requiring each one to be satisfied.

// The user must satisfy both the default policy
// and CanCreateWidget
[Authorize]
[Authorize("CanCreateWidget")]
public IActionResult New()
{
    return Ok();
}

This duplication will quickly get out of control though. Every time we want the default policy to be applied in addition to another policy, we’ll need to add multiple [Authorize] attributes to the controller and/or action. A better alternative is using AuthorizationPolicyBuilder.Combine. Combine lets us combine one policy into another. We can use that to combine our default policy into out CanCreateWidget policy. Now, any changes we make to our default policy will always be applied to CanCreateWidget without duplication.

public void ConfigureServices(IServiceCollection services)
{
    ...

    services.AddAuthorization(options =>
    {
        options.DefaultPolicy = new AuthorizationPolicyBuilder()
            .RequireClaim("AccountActivated")
            .Build();

        options.AddPolicy("CanCreateWidget", policyBuilder =>
        {
            policyBuilder
                .Combine(options.DefaultPolicy)
                ... setup your policy
                .Build();
        });
    });

    ...
}

I’m pretty happy with how this works now. Our default policy at Husmus is moderately complicated and we almost always want it applied when adding a more specific policy. Combine allows us to do that and still keep our policy configuration centralized in one location.

Using validateStatus in Axios

This past week I was working with an API endpoint where a 404 response is expected for invalid user input. I didn’t want Axios to treat this as an error. It had been awhile since I last needed to do this, but reading through the request configuration docs I was reminded of validateStatus. By default, it will return true for all 2xx and 3xx responses.

validateStatus: (status) => {
  return status >= 200 && status < 300; // default
},

In this case, I want the promise to resolve for 404 responses as well.

validateStatus: (status) => {
  return (status >= 200 && status < 300) || status == 404;
},

And that’s it. When the user puts in invalid input, the promise will still resolve. This isn’t something you often want to do, but it’s good to keep in mind depending on what a 404 actually means for your use case.

Custom Model Binders in ASP.NET Core 6

This past week I was integrating with a third party service that passes back boolean values in the query string as Yes/No. The built-in ASP.NET Core 6 model binding can handle true/false or 1/0, but not Yes/No. Let’s look at how to make our own custom model binder for this simple use case and how to unit test it.

Implementing IModelBinder

The official documentation provides a good overview of custom model binding. In this case, I implemented IModelBinder as follows

/// <summary>
/// Binds "Yes" or "No" (ignoring case), to true and false respectively.
/// Does not bind anything on other values.
/// </summary>
public class YesNoBooleanModelBinder : IModelBinder
{
    public Task BindModelAsync(ModelBindingContext bindingContext)
    {
        if (bindingContext == null)
        {
            throw new ArgumentNullException(nameof(bindingContext));
        }

        var modelName = bindingContext.ModelName;

        var valueProviderResult = bindingContext.ValueProvider.GetValue(modelName);

        if (valueProviderResult == ValueProviderResult.None)
        {
            return Task.CompletedTask;
        }

        var value = valueProviderResult.FirstValue;
        if (string.Equals(value, "Yes", StringComparison.InvariantCultureIgnoreCase))
        {
            bindingContext.Result = ModelBindingResult.Success(true);
        }
        if (string.Equals(value, "No", StringComparison.InvariantCultureIgnoreCase))
        {
            bindingContext.Result = ModelBindingResult.Success(false);
        }

        return Task.CompletedTask;
    }
}

Even though my current use case is just for query strings, implementations of IModelBinder aren’t specific to where the data is coming from. The data is gathered from a variety of sources. By the time the custom IModelBinder executes, the data has already been gathered and added to the ModelBindingContext, along with the name being bound to.

How It Works

var modelName = bindingContext.ModelName;
var valueProviderResult = bindingContext.ValueProvider.GetValue(modelName);

if (valueProviderResult == ValueProviderResult.None)
{
    return Task.CompletedTask;
}

First, I pull the data out of the bindingContext by name and confirm that a match was found. If not, don’t set any result on the bindingContext and just return Task.CompletedTask.

var value = valueProviderResult.FirstValue;
if (string.Equals(value, "Yes", StringComparison.InvariantCultureIgnoreCase))
{
    bindingContext.Result = ModelBindingResult.Success(true);
}
else if (string.Equals(value, "No", StringComparison.InvariantCultureIgnoreCase))
{
    bindingContext.Result = ModelBindingResult.Success(false);
}

return Task.CompletedTask;

Next, pull out the first value in the result. Binding works with collections, but in this case there should only be a single value. Then make case-insensitive comparisons against the bound value looking for Yes/No and only set a result for Yes/No values. Anything else will not bind at all.

Usage

If your use case is better handled without an attribute, then you can implement IModelBinderProvider. This is a good idea if you always want the custom binder to be applied. In this case, I want to opt-in to the binding with an attribute.

[HttpGet]
public IActionResult Index([ModelBinder(BinderType = typeof(YesNoBooleanModelBinder))] bool isValid)
{
    ...
}

When executing the binder bindingContext.ModelName will be isValid.

Unit Testing

The next step was to figure out how to setup ModelBindingContext for unit tests. I ended up with this. Assertions are handled with FluentAssertions

public class YesNoBooleanModelBinderTests
{
    [Theory]
    [InlineData("Yes", true)]
    [InlineData("yes", true)]
    [InlineData("No", false)]
    [InlineData("no", false)]
    public async Task BindModelAsync_returns_success_with_with_expected_value(
        string modelValue, bool expectedResult)
    {
        // Arrange
        var modelBinder = new YesNoBooleanModelBinder();
        var bindingContext = BuildBindingContext(modelValue);

        // Act
        await modelBinder.BindModelAsync(bindingContext);

        // Assert
        bindingContext.Result.IsModelSet.Should().Be(true);
        var model = bindingContext.Result.Model as bool?;
        model.Value.Should().Be(expectedResult);
    }

    [Fact]
    public async Task BindModelAsync_does_not_bind_if_model_value_is_not_yes_or_no()
    {
        // Arrange
        var modelBinder = new YesNoBooleanModelBinder();
        var bindingContext = BuildBindingContext("invalid");

        // Act
        await modelBinder.BindModelAsync(bindingContext);

        // Assert
        bindingContext.Result.IsModelSet.Should().Be(false);
    }

    private ModelBindingContext BuildBindingContext(string modelValue)
    {
        const string ModelName = "test";
        var bindingContext = new DefaultModelBindingContext
        {
            ModelName = ModelName
        };

        var bindingSource = new BindingSource("", "", false, false);
        var queryCollection = new QueryCollection(new Dictionary<string, StringValues>
        {
            { ModelName, new StringValues(modelValue) }
        });
        bindingContext.ValueProvider = new QueryStringValueProvider(bindingSource, queryCollection, null);

        return bindingContext;
    }
}

The important bits are in BuildBindingContext. ModelBindingContext is abstract, but the framework provides a DefaultModelBindingContext that we can instantiate. The BindingSource is not relevant for our tests, but must be provided. The QueryCollection will feed into the QueryStringValueProvider that we pull values out of in the YesNoBooleanModelBinder implementation. In this case we’re saying the data came from a query string, but you could use another implementation of IValueProvider, such as RouteValueProvider. You can see an example of that https://stackoverflow.com/a/55387164/235145

100 Days of Morning Pages

Morning Pages are three pages of longhand, stream of consciousness writing, done first thing in the morning. *There is no wrong way to do Morning Pages*– they are not high art. They are not even “writing.” They are about anything and everything that crosses your mind– and they are for your eyes only. Morning Pages provoke, clarify, comfort, cajole, prioritize and synchronize the day at hand. Do not over-think Morning Pages: just put three pages of anything on the page…and then do three more pages tomorrow.

Julia Cameron (https://juliacameronlive.com/basic-tools/morning-pages/)

I’ve been journaling semi-regularly for years. On August 21 I sat down at my desk and wrote morning pages for the first time. I missed a couple of days, but after 100 entries, it’s a good time to reflect on the value of the habit for me.

Longhand vs. Typing

I wrote the first couple of months of entries longhand as Julia recommends. This took me about 30 minutes each day. However, after finishing my first notebook (about two months), I decided to try switching to typing for a bit. This goes against her recommendation but is working well for me. It’s an exercise in tradeoffs.  When writing longhand, I am slow enough that my internal monologue is almost always ahead of my hand movements. When typing, that isn’t always the case. It’s taken practice to get to the point where I don’t stop typing even when I don’t know what to type next. I resort to asking myself rhetorical questions more often about the fact that I don’t know what to type about next. This would occasionally happen when writing, but much more often when typing. In the time it takes to type out that rhetorical question, a new thread of thought usually appears that I can follow. And since I type so much faster than I write, I’m done in about half the time.

Even when writing in my journal, I would take pictures of each written entry and add them to Evernote. Now I just type directly into Evernote. I’ve done various forms of journaling with varying success for many years. Keeping everything centralized has value to me. When writing longhand, I missed being able to search for some random thought I know that I wrote down sometime in the past couple of weeks.

Overall, I’m pretty happy with the switch to typing. Taking only half the time and being able to search makes breaking the recommendation worth it to me.

Clearing My Head

For me, writing morning pages has not helped clear my head to any noticeable extent. It continues to be a jumbled mess. What it does do though is provide a routine to start my day with. Well, it tries to. The problem is that my mornings vary depending on if I’m taking the kids to school that day or not. The real solution here is to adjust my sleep schedule to get up a bit earlier, but I haven’t been willing to do that.

On mornings where I am not responsible for getting the kids ready and to school, the routine does help. I get ready for the day, make my tea, and head to my office. My morning pages often meander into what I want to get done at work for the day, helping to seed my task list. From years of experience, I know that I do my best work when I break problems down into small chunks. Days where my morning pages can transition directly into planning out my day are commonly my most productive.

Morning Pages as Therapy

This was not intended, but my notebook of longhand writing became a source of therapy. A couple of weeks after I started the habit, my dad was (not unexpectedly) diagnosed with terminal cancer. 23 days later he was dead. The journal morphed into a treasured possession containing many of my thoughts as he died in front of me. A couple of entries are filled with stream of consciousness writing for a eulogy. Many of those ideas made it into the one I gave. Events moved fast during those weeks. Having a record of my daily thoughts during that time is incredibly valuable to me.

Even if you’re not going through something that intense, stream of consciousness writing can be very valuable to help work out problems. It can be hard to turn off your filter, something I still struggle with. With regular practice though you can get better. Remember, these thoughts are for you and no one else.

Give It A Shot

Overall, I recommend giving morning pages a try, either written or longhand. Clear out some time at the beginning of each day, grab some tea, and dedicate yourself to the habit for at least thirty days.