August 9

Monday to-do list:

• Do code reviews.
• Continue integrating tracing throughout kanidmd.

Monday started out like most other days with some good ‘ol fashion code review. Nothing too wild, but I was able to ask good questions as well as make some aspects more idiomatic (which is definitely my favorite part of code review). After reviewing William’s code, I responded to some clarifying questions on my own draft PR.

I ended up getting heavily distracted with web scraping in Rust, and made a cute little program using Selenium and chromedriver to go to a website, press some buttons to generate a haiku, and then text it to someone via iMessage using osascript. Not at all related, but still fun :)

After I finished that mini project, I continued working on making the span names more descriptive for functions they were associated with. I also realized that I was probably overusing the TRACE level and should make spans opening be at the INFO level, but ultimately decided against it.

Further continuation with the tracing integration resulted in me getting realllllly frustrated trying to trace where an AuditScope was being passed around. I came across an area where there approximately 5 traits with default implementations all calling each other and then at the very end, a non-default method making it super obfuscated to find what code was actually being called. This meant I had to figure out which objects the traits were representing so I could find the type-specific implementation of a method at the very end. Not an enjoyable experience.

I realized my brain was pretty much toast, so I called it a day there and passed that problem onto future Quinn. You’re welcome, me :)

August 10

Tuesday to-do list:

• Review comments on draft PR.
• Continue kanidmd integration.

I started the day by reviewing the comments on my draft PR- more clarifying questions I had to respond to. I also reviewed the responses to my questions on Adding stricter headers, which helped me understand how the code changes worked. Everything seemed pretty reasonable to me, so I approved it for merging!

Afterwards, I continued integrating tracing in parallel with AuditScope. This constitutes following where AuditScope gets passed around in functions, and adding tracing logs wherever there are audit logs. Classic DFS. I also started tagging functions that had full tracing integration with a comment, allowing me to save a lot of time digging because my editor let me preview a function definition from wherever it’s called, allowing me to see whether a function had integration without having leave my current file.

I also began to realize that all the fmt::Debug implementations were getting really annoying to look at, and that some types could definitely be represented more clearly in logs using a custom fmt::Display implementation. One way I envisioned this was by finding some nice serde format, and then deriving Serialize for a bunch of things. However, I decided that this wasn’t worth pursing at the moment, and put the idea on hold for a future PR.

While I was marking tags, I realized there were SO. MANY. functions that also used an AuditScope that weren’t direcly in the tree of function calls I was using, but I didn’t have time to go through and integrate tracing for all of them, so I marked them with a TODO (Quinn) so I could come back later with git grep when working on full integration.

At first, I wasn’t sure about the benefit of not having to pass an AuditScope object around. However, after seeing how many stack frames its passed through just to, for example, reach a conditional that might log one thing, I acknowledged that switching to tracing was a great idea.

August 11

Wednesday to-do list:

• Prepare PR for merging.

William wanted to integrate my work incrementally, meaning I had to get my PR into a mergable state by the end of the day. I wasn’t quite on board with the “let’s merge a work-in-progress feature” philosophy, but I also figured it wouldn’t detrimentally hurt anything once I got it to a mergable state. And since it was William’s idea after all, I was off the hook if things went south.

Prepare for a bunch of code snippets below. I like writing Rust, a lot.

One pattern I realized showed up a lot was logging an sqlite error:

some_sqlite_function()
    .map_err(|e| {
        ladmin_error(au, "SQLite Error -> {:?}", e);
        OperationError::SqliteError
    })?;

This showed up a least a couple dozen times, and I wanted to abstract it into its own unified function. I wasn’t entirely sure why we didn’t do this before with something like:

fn sqlite_error<'a>(au: &'a mut AuditScope) -> impl 'a + FnOnce(rusqlite::Error) -> kanidm_proto::v1::OperationError {
    |e| {
        ladmin_error(au, "SQLite Error -> {:?}", e);
        OperationError::SqliteError
    }
}

… since this would’ve enabled us to do:

some_sqlite_function()
    .map_err(sqlite_error(au))?; // assuming `au` is `&mut AuditScope`

Of course, this probably compiles into the exact same machine code. It’s just much more pleasant to look at.

With tracing, however, this abstraction becomes even simpler because we don’t need to store a reference:

fn sqlite_error(e: rusqlite::Error) -> kanidm_proto::v1::OperationError {
    admin_error!(?e, "SQLite Error");
    OperationError::SqliteError
}

… allowing us to write:

some_sqlite_function()
    .map_err(sqlite_error)?;

Much better! I was going to wait until after most of the changes were done because I wanted it to first get approved before I went around cleaning things up and optimizing, but then I got super annoyed at pasting in my tracing log macro right in the same chunk of code every time so I just implemented it right away. Big improvement!

I also came across a macro I hadn’t seen before: limmediate_warning. This was essentially the same as my alarm macro, except with a different error level. I realized that instead of having custom behavior for super urgent logs, I should instead just have an optional immediate field that, if set to true, will also print to stderr. That way, I wouldn’t have to conceal hidden magic behind the alarm macro.

Implementing the immediate field wasn’t particularly hard since it was essentially just doing what alarm did under the hood, and I liked the implementation a lot more because it meant less information hidden behind macros :)

I also ran into a similar pattern to rusqlite errors with serde_cbor errors, so I also made a serde_cbor_error utility function to plug into macros, and was able to clean up even more code!

I was able to completely finish integration for kanidmd/src/lib/be/idl_arc_sqlite.rs and kanidmd/src/lib/be/idl_sqlite.rs, since they seemed mainly responsible for logging the code that gets run when logging into the server from the CLI, which I was using for preliminary testing. My next steps were to continue on things in kanidmd/src/lib/be/mod.rs, but I was feeling worn out and still had to get my branch in a mergable state. I spent more time making sure everything was in order before pushing in preparation for merging. I ended up working longer than I intended too and was exhausted by the end of the day, but I was super proud of all that I’d done.

August 12

Thursday to-do list:

• Continue integrating tracing.
• Do more testing besides just logging in from the CLI.

Did not end up merging from Wednesday, turns out there were a few minor changes William wanted done.

Thursday began with the overnight realization that (non-async) functions with a span wrapping all the functionality should just use Span::in_scope because it’s more analogous to lperf_trace_segment, and would make removing AuditScope at a later stage much easier. However, that got a bit repetitive because I had to write the same snippit for each function:

trace_span!("span name").in_scope(|| {
    // function body
})

I decided to create my own spanned macro that would mimic this behavior. One cool thing is that I enabled it to accept a closure or just a block, meaning I can choose whether or not I want to catch return or ? inside the span or let them short circuit the other function. This didn’t make a difference for spans wrapping entire functions, but there was a particular case where a piece of code inside of an lperf_trace_segment used short circuiting to exit the segment, but not the outer function. When it comes time to remove AuditScope, I can keep that code in a closure for spanned to prevent it from short-circuiting the entire function!

While I was implementing this, I was particularly reminded of this blog post by Without Boats, talking about how Rust’s support for higher-order functions and control-flow is pretty poor.

Moving on, I ran into a brick wall in my refactor-thon: I needed to be able to access the current operation UUID in one of the functions. This was trivial with AuditScope, but I didn’t have any functions for accessing it from within my own tracing implementation.

I spent 30 minutes searching through what tracing’s macros were doing in order to access the global subscriber. I figured if I had to access the global subscriber, I could get its Context and use that to do lookup_current to get the current span, and from there I could take its UUID or parent UUID, whichever came first. Great! I wasn’t happy about having to parse it back into a UUID though. Storing the Uuid as two u64’s was definitely going onto my to-do list.

August 13

Friday to-do list:

• Figure out how to get the current span’s UUID.
• Finish ongoing changes, rebase and prepare for merging.

I spent a lot of time digging through tracing’s documentation, trying to figure out how to get access to a span’s UUID. However, I was struggling because my only entry to getting any tracing information was with tracing::dispatcher::get_default, which gave me a &Dispatch, containing my TreeSubscriber as a dyn Subscriber, meaning I couldn’t have any implementation-specific behavior I could trigger via that function. After another 45 minutes of digging in the docs, I found / recalled downcast_ref, which allowed me to downcast the Dispatch’s dyn Subscriber to any type that I wanted, and it would return an Option of the type, some being if it found that subscriber! This meant that I could have TreeSubscriber specific behavior that I could call from a Dispatch object. Amazing!

I put all the parts together in a cute little macro, but then remembered I hated macros, so I converted it to a standalone function. Now that I was able to get the current UUID of the operation, I was able to get back to business.

I spent the rest of the day integrating tracing in server::QueryServerTransaction and idm::account which was a mostly monotonous task, and pushed my changes to the branch. Going to rebase and finalize on Monday.

Weekly Reflections

My first week of really integrating my code into the code base! This week was fairly monotonous, but sometimes those weeks are just as necessary as weeks with lots of exploration and discovery. I was reminded of my first few weeks back on the project, where I was engaged with many different parts of the project on a very shallow level, since I was just sweeping through so many files without really paying attention to what they were doing and just integrating my tracing functionality.

Reflecting back on my first summer goal to expand my Rust knowledge, I thought my analysis of allowing the spanning macro to either accept a closure or just a block to choose how control-flow operators like return and ? were handled was really cool, because I was able to relate it towards a blog post that made me realize the problems I was having are part of an advanced, well defined area of mathematical theory. I also learned new Rust cheat techniques with my usage of downcast_ref, which allowed me to break the barrier of a trait object being too abstract. This reminded me of when I made a Python extension written in C, and each object would have a PyObject at the top of the struct, allowing cpython to cast pointers of any object to a PyObject. This example is more “boilerplate-y”, but the concept of casting to a pointer of a different type is the same. These breakthroughs definitely expanded my breadth as a software engineer outside of just Rust, which I’m really proud of.