For about two weeks I had a curious bug in Cascade Chat: it could connect to Libera.Chat just fine and then disconnect a few seconds later. It wasn't failing quietly somewhere in the middle of authentication either. Cascade completed SASL, the login exchange it uses to authenticate with the server. Libera then sent the messages confirming registration. Cascade had even started joining channels before the socket disappeared.
Depending on how broadly I count, fixing this took seven related PRs between July 3 and July 15. They were a few recurrences of the same connect-then-disconnect behavior rather than one continuous debugging session, although the final recurrence still took four attempts. This was a lot of work for a bug whose visible behavior amounted to “it connected and then it didn't.”
When I first wrote about Cascade Chat I described IRC as a complex event-driven architecture. That was accurate, but at the time I was mostly thinking about how IRC messages moved through the application and how plugins would subscribe to them. I wasn't thinking enough about the resources those paths shared or what would happen as more integrations accumulated behind an otherwise simple callback, which is just a function the IRC library runs after receiving a particular kind of message.
Event-driven systems are pretty easy to assemble. Something happens, the application emits an event, and another part of the application reacts to it. The difficult part comes later when those reactions include database work or something outside the process and the original event is still somehow waiting for all of it.
It wasn't the handshake
The first useful fact was that Cascade really had connected. Libera accepted SASL and finished IRC registration. The client had already started loading its saved channels by the time the connection went away, which put the problem after the stage I had initially suspected.
One of the early changes surfaced the underlying network error in the server buffer:
remote host closed the connection (EOF). Previously the UI only had a generic disconnect message.
An IRC ERROR would've contained an explanation from the server. An EOF only told me Libera had
closed the network connection, so I still don't know the server's exact reason for doing so. What I
can explain is the client behavior leading up to the EOF, which is the part I could reproduce and
eventually change.
Cascade was joining fourteen saved channels at startup. Some of them were busy enough to have well over a thousand users. Joining an IRC channel produces a roster, which is the current list of users in that channel. Cascade persisted each user's record before publishing updates for the frontend. Plugins subscribed to some of the same data. Much of this path was also being logged synchronously, meaning the logger had to finish its work before processing could continue. A single join could turn into thousands of operations inside the application, and startup did that across every saved channel in a fairly short period of time.
Layers of wrongness
What made the earlier fixes interesting is that I can't dismiss them as dead ends. They all removed real problems.
During registration an IRC client asks the server which optional features it supports. Cascade had been asking for roughly fifteen of them one at a time, which made registration slower and put unnecessary traffic on the connection. That became one filtered request.
Cascade's EventBus sat between the code producing internal notifications and the parts of the application consuming them. It used one background dispatcher so events arrived in order, with a buffer to hold anything published while that dispatcher was busy. The buffer was deliberately capped at 1,024 events so a slow consumer couldn't cause Cascade to use an unlimited amount of memory. That number was an application choice rather than an IRC limit, and it looked comfortably large for ordinary chat traffic.
A large roster was not ordinary traffic. In another reproduction about 1,900 user records filled the buffer. Once every slot was occupied, publishing the next record waited for a consumer to catch up. Since the publisher was also responsible for reading IRC messages, the socket stopped being read while it waited.
Updates describing users, such as their nickname colors, moved to a background path as part of that fix. When several updates for the same user were waiting, Cascade could keep the newest one rather than making the consumer process every intermediate version.
At one point simply selecting an already joined channel caused Cascade to send NAMES, the IRC
command used to request a channel's current user list. On ##programming that meant asking Libera
for roughly 840 users Cascade already knew about. Removing that request fixed a pretty silly network
side effect, but a legitimate large roster could still cause the same disconnect.
The next reproduction showed 791 users from ##chat being written to SQLite with a separate
transaction for every nickname. Batching the roster made that dramatically cheaper. Then the
nickname-color plugin expanded the batch back into hundreds of individual updates describing those
users. Those plugin updates needed batching as well. Cascade's plugins run as separate processes and
receive newline-delimited JSON messages over their standard input. Those messages needed a size
limit so one huge notification couldn't break a plugin's message reader.
There was more work after that around synchronous logging and frontend roster updates. Important events also needed to get through when roster updates were filling the queue. An event reporting that the IRC connection has gone away cannot be skipped without leaving the application in the wrong state. A roster update is different because it is a complete view of the channel's members at that moment. If a newer roster is already waiting, the frontend does not benefit from rendering the older one first. Cascade could discard that older copy while still guaranteeing delivery of the disconnect event.
By this point the application was doing much less work and one live run processed rosters containing more than 1,700 users without disconnecting. The tests passed and the observed bottlenecks were gone, so the result looked convincing.
The user installed the update and reproduced the disconnect.
I had been treating each bottleneck as though removing it made the connection path safe. What the changes actually proved was much narrower: one database operation was cheaper or one part of the application could no longer fill a particular queue. None of them answered why application work had any say in whether the IRC socket was allowed to keep reading.
What the diagram left out
Cascade's event flow looked reasonably decoupled when drawn at the component level:
The diagram is accurate as far as where data goes. It says nothing about which component has to wait while another component works, which turned out to be rather important.
The IRC library read a message from the socket and invoked matching callbacks serially. It did not read the next message until the current callbacks returned. Cascade had about 79 application callback registrations across the various IRC commands and events. Every message did not invoke all 79, but whichever callbacks matched were running on the same Go goroutine, or lightweight thread, that was responsible for reading the socket.
Following which component was waiting instead of the arrows between components produced a much less comforting picture:
plugin stdin <- EventBus <- application callback <- socket readerA callback might write to SQLite before publishing into the event bus. Somewhere downstream a plugin could be slow to read from the connection Cascade used to send it messages. Synchronous logging made the callback do even more before the library got around to reading the next IRC message. If any queue in between filled up, the fact that a queue existed didn't help the socket reader; the callback simply blocked while publishing to it.
I had treated emitting an event as a form of decoupling when it was really only an interface. The source code no longer knew much about its consumers, but the socket reader could still depend on how quickly those consumers completed their work. Making a queue larger would've delayed the problem without changing that relationship.
The requirement I should've started with was that application work cannot prevent the IRC client from continuously reading messages from its socket. Once I looked at the system from that direction, optimizing callbacks one at a time was clearly never going to establish the boundary I wanted.
Moving the callbacks wasn't quite enough
The first version of the final fix transferred application callbacks to one background processor. It handled callbacks in the order they arrived, so moving the work didn't change the sequence in which Cascade saw IRC events. The socket reader could hand the work over and immediately return to IRC.
That version disconnected during live testing too, but the result was useful. The socket reader was now free and none of the observed application callbacks in that run took longer than 100 milliseconds. The remaining failure came from work traveling in the other direction.
After Cascade sees its own user join a channel it can send WHOX, which asks for more information
about the users than the basic roster provides. It also loads recent stored messages through
CHATHISTORY where the server supports it. Those callbacks had previously been delayed behind the
application backlog. When the new background processor caught up, a group of them sent their
requests close together. The requests were small on the wire, but each one could prompt Libera to
return hundreds of roster or history records. Measuring only the bytes Cascade sent would've missed
almost all of their actual cost.
The fix in PR #185 therefore separated incoming callbacks from automatic outbound requests. Application callbacks kept their background processor. Automatically generated IRC requests went through another one that sent each request in sequence with a short delay between them. Requests for extra user information waited for the initial roster to finish. When the connection closed, Cascade discarded any unsent requests belonging to it.
I ran five consecutive Libera reconnect cycles against the final version. Cascade completed all 70 expected rosters across the fourteen channels, including rosters larger than 1,700 users. I kept the nickname-color plugin enabled and switched through busy buffers during the startup load. There were no unexpected EOFs.
Five cycles was enough to give me confidence that the reproduced failure path was fixed. It also gave me a much better workload for validating connection changes than joining one small local test channel and calling it good.
Following an event from front to back
I still think events are a natural fit for Cascade Chat. IRC itself is event driven, and having plugins or the frontend subscribe to what is happening in the backend makes sense. The part I got wrong was assuming that an event boundary carried more architectural meaning than it did.
Backpressure, meaning what the system does when work arrives faster than it can be processed, is now something I think of as part of the interface rather than a detail of the queue implementation. A connection-loss event has to remain ordered because missing it leaves the application in the wrong state. An older view of a channel roster can be replaced when a newer one is already waiting. Plugin delivery needs a limit because a subprocess that stops reading stdin shouldn't control the network connection. Automatic IRC requests have to account for how much data the server will send back, not just the size of the request.
The primary challenge is that each integration point requires rethinking the consequences to the system from front to back. Adding a subscriber may be a small code change, but I still need to know which resource produced the event and whether the subscriber can delay it. I need to follow any new work it creates, especially when that work crosses back onto the network. Reconnects complicate the picture further because queued work can outlive the connection that created it.
Honestly, this is part of what I like about maintaining Cascade. A bug can begin as a fairly bland EOF and end up changing how I understand the whole application. Cascade now handles the startup load that used to knock it offline, while the earlier fixes left the surrounding event paths in much better shape.
Events remain a natural fit for Cascade. I also have a better way to think about the next integration: follow its effects from front to back and find which resources it can make wait. That feels like a useful outcome from a curious little disconnect bug.