July 26

Monday TODO list:

• Research tide::Middleware.

Monday began with researching tide, a web framework used in Kanidm that William suggested for the entry point for my tracing integration. I’m still not entirely sure of the capabilities of tide at the time of writing, but I know it streamlines the process of serving web requests. My job was to identify how to integrate my TreeSubscriber implementation with tide::Middleware, which would allow me to insert my logger as a passive observer of web requests and responses.

As many days start, I began by navigating around the documentation. The implementation details initially looked intimidating, until I found that there was a LogMiddleware type that implemented tide::Middleware already. Since it already contained all the behavior I needed, I ended up copying most of the implementation details and swapping the logging to work with tracing. I would say my experience interacting with tide was vastly smoother than tracing, and I wasn’t sure if this was because I was a better Rustacean, if I wasn’t writing much original code, or if tide was just a fundementally simpler library to use.

Even though my tide::Middleware implementation was simple, I already got to use pieces of TreeSubscriber like the custom macros! It was such a cool feeling to create code meant for others to use, and then using it to write meaningful code yourself outside of test cases. It really made me appreciate the amount of effort I put into my code to make it usable for others.

And just like that, my implementation… was finished? The process felt way too simple, but I also wasn’t entirely done because I didn’t know how to test it. I ended up coming up with a very simple way to test logs, but for some reason the subscriber wasn’t picking up on logs that were happening inside of the middleware. I outlined my issues in an email to William and called it a day.

July 27

Tuesday TODO list:

• Add configurable outputs for logs

William got back to my email, but he suggested that the reason it didn’t work was because TreeSubscriber wasn’t a global type, and that it instead should serve as an AuditScope replacement. I felt a little dishonored because:

1. tracing’s whole appeal is based on asynchronous logging; of course it’s capable of being a global type, and
2. I didn’t want him to think I was just rebuilding something we already had.

TreeSubscriber was going to be vastly superior to AuditScope, and I was going to prove him wrong :)

Fueled by my determination to exceed William’s expectations, I set out to find for myself why the subscriber wasn’t working. A few futile attempts later resulted in resorting to tracing::subscriber::set_global_default, which worked like a charm! I was originally opposed to using it, but it made a lot of sense because I wanted the subscriber to be initialized once and then forgotten. It’s also wrapped around a highly optimized sharded_slab type that allows for efficient shared mutability to minimize blocking, so I wasn’t worried about performance.

I was really satisfied with the result, since after initialization, my example looked like this:

let mut app = tide::new();
app.with(TreeMiddleware);
app.at("/").get(|_| async { Ok("Hello, world!") });
app.listen("127.0.0.1:8080").await.unwrap();

No tracing behavior in sight aside from dropping in a ZST for the middleware.

AuditScope, on the other hand, requires you initialize one for every tide request 🥴, pass it around every function 🤢, and pass it into log macros 🤮. Sickening stuff, really.

I was going to have the outputs be configurable for each individual span, but I decided that was too much of a hassle and decided to only have it configurable for spans in the root. I got this to work on the first try!

However, I came across a weird bug: my code was panicking after writing to the file once. I was confused, because I thought the file was getting nicely opened and closed again because of Rust’s nice drop semantics on std::fs::File, but I wasn’t sure that was the problem.

A bunch of digging around on StackOverflow revealed that instead of using the basic File::open and File::create methods, I should be using the more customizable OpenOptions type that allowed me to get all my functionality built-in. This made my tests work!

I also ended up changing the TreeMiddleware type to take an output as a &str for where it should write to, since it couldn’t pass custom types through tracing’s field boundry. This information is stored in the event tree, which is passed back through the channel for formatting. The TreeProcessor uses this information to know where to send the logs after processing and formatting.

Now it looks like this:

// Write to `test_out/middleware_test.log`
app.with(TreeMiddleware::new("test_out/middleware_test.log"));

// Or write to stderr
app.with(TreeMiddleware::new("stderr"));

Since I wasn’t quite sure where to go next, I texted William my progress updates and decided to call it a day.

July 28

Wednesday TODO list:

• Code review.
• Continue tracing implementation through tide::Middleware.

Code review was pretty straightforward, and only took ~30 minutes.

I also made some changes to my new TreeMiddleware type. I gave it custom constructors for stdout and stderr, making it cleaner and easier to direct logs to the correct output. I was initially confused on where to start in Kanidmd, but I found the entrypoint for tide applications in core/https/mod.rs, and was able to insert my tracing logging middleware there and start adding in my customized logging macros in parallel.

July 29

Thursday TODO list:

• Finalize code review.
• Continue integration with `kanidmd.

Code review was way faster than I thought, William basically said to keep in mind that a lot of the content is a placeholder for future expansion. I was happy to see my “inner clippy” feedback was incorporated, since we were able to remove a closure from an iterator. Then, I shifted gears towards tracing-tree, the new name I gave my project.

I fiddled around with server things for a bit but I still wasn’t sure how to run the server to test logging. I went back to the GitHub converation where we talked about it, but there wasn’t much I didn’t already know. I ended up sending a draft PR here because I wanted detailed feedback and I needed to show what I already had.

July 30

Friday TODO list:

• Review comments on draft PR.
• Follow instructions for setting up server instance to test logs.

Friday morning started with reviewing William’s feedback for the draft PR I sent Thursday. I clarified a few things in my code, but not much else changed. I added examples of pretty and JSON logs for James to look at, too.

Then I got to the real meat of Fridays work: setting up a development server. William sent me instructions on how to get it up and running on my computer, and I got the server working! Unfortunately, I don’t know how to login since I just have a password and I don’t know my username, and the interface asks for a username. But I later realized it was because I set up the credentials awhile ago and probably entered a username there so I had to redo most of the process. Oops.

I got things somewhat figured out and started repeatedly logging in, seeing what logs appear, and git greping to find where they’re generated, and tossing in some tracing logs in there. For async functions, I used the #[instrument] attribute macro, and for regular functions, I added an entered span object:

let _entered = trace_span!("span name here").entered();

It was pretty easy because I could just follow where logging goes by following where the AuditScope gets passed around. Even though this was convenient here, we didn’t want to have to think about logging otherwise, so it was good to eliminate it.

I also seriously underestimated the volume of logs that simple requests produce, and realized it would take me awhile to add logs in parallel for even tracing execution of a simple request. I decided to just work on adding some logs to where I could easily see things first, and later focos on flushing out the system with full on tracing-tree logs.

Ended the day having made amazing progress; my logs were looking really good! I pushed my current changes to my branch and left a comment on the PR. Nice!

Weekly Reflections

I’m super proud of the progress this week, since I think it might be the first week where significant portions of my code are being integrated within Kanidm! I think I’m also making great strides towards my goal of getting use to working with others’ code, as I integrated my logging implementation with tide::Middleware, and was able to start implementing that within Kanidm too. I think these skills I’m developing now will be critical towards contributing towards future projects, both open source and at whatever company I end up at. Also, I spent the last few weeks doing innovating and not a lot of tying things together, so this was a nice change of pace.

I also took this week (Aug 1 - Aug 7) off to go backpacking! Coding and blog posts resume next week!