June 21

Monday TODO list:

• Review comments on Oauth2 PR #485.
• Attempt to resolve the fragile tests issue #486.
• Revisit tracing-logging #467.

William suggested in the code review that I add a clippy lint for |s| s.to_string() -> str::to_string. I was initially going to create my own, but that seemed overly complicated and I found an existing one. However, I couldn’t figure out how to apply it in the project, so I left a comment and linked it in the code review.

I was also curious about what Filters were, since I kept seeing them sprinkled everywhere throughout the PR. It turned out that they’re analogous to SQL queries, where they assert if a set of properties holds true on an entry or a set of entries.

After I finished the code review, I went to figure out which functions were untested for the fragile tests issue I opened last week. I removed the fixes and tested each function one by one, but somehow all of them already had tests. I swear this wasn’t the case when I was fixing it last week, but I also wasn’t complaining because it meant I got to check off another thing from my todo list and close the issue.

I tried to work some more on tracing-logging #467. Although I was able to find the place where I was getting logs, I got stuck because I didn’t want to make any dramatic changes and break anything. I eventually came up with some questions for the area I was poking around in so I could understand it better before trying to tear into it and make big changes, and left them in a comment on the PR.

I also asked William if I should open an issue to rewrite the macros in audit.rs to be methods of the AuditScope type. I hoped that this would help me understand the code, reduce the use of macros which are less predictable than functions, and ultimately help me implement the tracing logging more easily.

June 22

Tuesday TODO list:

• Looking into implementing tracing in memberof.rs.

William responded to my questions, and suggested that I look into implementing tracing in memberof.rs since it was already well tested and benchmarked. I was a bit intimidated because the AuditScope stuff seemed so deeply integrated in memberof.rs that it was hard to dig through everywhere to find what’s being logged. I also got frustrated that everything was defined within a macro, because VSCode can’t offer support when analyzing macros (no type hints, can’t CMD+click to find definition).

The first thing I did was figure out how to redirect stdout and stderr to their own files, since there were too many logs and I needed CMD+F. I had a strange issue where my tracing logs had random characters sprinkled throughout them. Some StackOverflow digging revealed that they were caused by tracings default ANSI encoding, which I found out how to disable by digging through the docs.

I was getting very frustrated having everything wrapped in macros, so I foolishly spent an hour converting them all to methods for AuditScope so I could get my VSCode support and other guarantees that function provide that macros don’t (potentially better optimizations, guaranteed isolation from parent scope, etc.). I left a comment on the PR, and left it at that. I later found out that making big changes without consulting people is a bad idea.

I still stand by my opinion that functions »> macros when possible, but I understand that changing this was not a good idea for other reasons. Oh well.

June 23

Wednesday TODO list:

• Fix logging stuff

Wednesday started off very sad because I had to revert the changes made on Tuesday regarding changing macros to methods. Oops. I decided to focus on acheiving the MVP for my tracing implementation.

The first issue I ran into was how to send logs to stderr instead of stdout. All the AuditScope logs were getting sent to stderr and I wanted my logs to go there too, instead of getting mixed with the other junk printed to stdout. I wasn’t quite able to figure it out, but I knew it was probably somewhere in the tracing_subscriber crate.

One cool thing I realized is that you could add attributes to logs in tracing, and this served as the perfect replacement for how we had named log macros current for the AuditScope type. For example, there’s ladmin_info, ladmin_warning, and ladmin_error. We could add an admin attribute to each log to retain this same information. I still had to do a lot more research though, because I still didn’t fully understand it.

Ended the productive day by leaving a comment on the PR, in hopes that William would be more receptive of the changes I’d made.

June 24

Thursday TODO list:

• Respond to William’s feedback on tracing-logging #467.
• Figure out how to time spans.
• Figure out how to withold log writes from Subscribers.
• Research multi-producer single-consumer channels (like std::sync::mpsc).

Thursday started off by (you guessed it) responding to feedback on tracing-logging. William mentioned that one of the special issues that AuditScope addresses is that it’s able to store all the logs in memory until we tell it to dump everything, at which point it acquires the stderr lock exactly once to write everything.

Figuring out how to time spans was relatively easy; I just read through the docs and found a setting that would log whenever a span ended, which also logged the time active and time alive. While I was digging around through the docs, I also figured out how to customize the human-readable log messages. This was helpful because the field-value mappings of each event were not formatted distinctively from the message, so I was able to address this. I even figure out how to finally redirect all the logs to stderr! Crazy how much you learn from reading the docs.

I still wasn’t really sure how to make Subscribers withold logs, unless I could come up with a custom type to have the Subscriber feed logs into, which certainly seemed like my best bet.

After some research, I decided to use a std::io::BufWriter as the default writer for a subscriber. This would allow us to write many logs without having to lock the thread on writes to stderr each time.

I implemented this pretty quickly and felt super proud of myself, but my excitement was short-lived. In my solution, I just made an empty LogBuffer struct that returned a BufWriter when make_writer was called because I thought it was only called once. It turns out that the make_writer function is called every time an event is recorded. This meant that my solution of returning a BufWriter was completely useless, because it would have created a new instance every single call, completely defeating the point.

In fact, it actually makes sense why they did this. I think it was intended to work with stdout and stderr, where an owned “guard” to the stream is returned when io::stderr and io::stdout is called. Since the Subscriber only needs access to the guard very briefly, it creates a new one for each log to minimize the amount of time holding it.

The fact that the output had to be an owned value raised another issue: I couldn’t simply return some type that referenced an owned BufWriter.

I was going to solve this issue by having LogBuffer hold a Rc<BufWriter<_>>. This seemed like a great idea because it meant I could call make_writer willy nilly, with the only cost being a ref counter being ticked up and down a couple ten thousand times, which really isn’t that bad compared to locking while waiting to get the stderr io stream. However, I realized that this meant we would hold the Stderr guard throughout the entire duration, which would lock stderr for the entirety of the time that logs are being collected. Not my brightest idea.

My new idea was to combine this shared ownership idea with what AuditScope currently does, where it collects all the logs internally to avoid holding any guards, and then writes them all with a dump method that consumes the buffer and writes the logs, only holding stderr for when it’s actually writing.

I initially implemented this using Rc, with the intent to use raw pointers later because our scope for shared data is so restricted that it would be simple. For example, there will semantically be one real owner, where the others are just references to the buffer in the form of owners to satisfy the make_writer type restrictions. I shortly realized I had to use Sync to satisfy some trait bounds, so I switched to using an Arc. I was not happy about the potential performance implications, but I decided to live with it.

With all the changed I’d been making, I was really finding out how slow the Rust compiler is. It felt like half of my time was spent waiting, even though my editor is opened directly into kanidmd crate. :(

After some fiddling, I finally got a working, safe implementation by using Arc and Mutex, which I was really unhappy about. I planned to replace this with raw pointers once I get more intel on the use cases, though. I ended up leaving a comment on the PR and calling it a night.

June 25

Friday TODO list:

• Review William’s new PRs.
• Work on eliminating use of Arc and Mutex in LogBuffer type.
• Split the tracing implementation into two PRs: one for unix_int, one for kanidmd.

Friday started off with code review. It was not as exciting as in the past, because the first PR had very few changes, and the second one had some changes since I last viewed it. The issue was it only showed me the updates file, and not the exact lines, so I had to review the entirety of the changed files. I later found out that this was because William had to do a git force, which did not play nicely with GitHub.

I spent some time figuring out how to use raw pointers, and was able to get everything with only one unsafe block! In the final version, calls to make_writer only involve copying a pointer, reducing LogBuffers overhead to practically zero. Awesome!

William also wanted me to split the tracing implementation into two PRs. I was able to do this by reseting my branch to the commit right before I started doing member.rs things, stashing the modified files, opening a new branch, and popping them into there. I’m really starting to get the hang of git! Once the changes were split among branches, I submitted a draft PR for my changes on memberof.rs.

Finally, I wrapped up the day by editing up this blog post.

Weekly Reflections

This week was a huge leap forward for me in terms of independence, confidence with git, and code writing. I was really happy that I got to do real problem solving with my LogBuffer type, since it was 100% my own code and not just editing someone elses code. Additionally, looking back at the start of my tracing-logging PR is very indicative of how far I’ve already come with git knowledgeability. I was super stoked when I was able to split my changes into two separate PRs without having any issues.