Potential race condition during startup

[jhillyerd]

tl;dr: during stratus startup, there is a tiny window where a socket message will go to the owning process/supervisor instead of the stratus actor.

Backstory

I have a project that talks to Home Assistant over a websocket. After upgrading to Stratus 2.0, my project stopped working. I eventually traced it back to not receiving the initial auth_required message from HA, which should be sent immediately upon connecting. I couldn't figure out the cause, so I let an LLM grind on it for quite a while, and eventually it found a race condition: there is a tiny window of time where a message will go to the owning process/supervisor instead of the stratus actor. My local home asisstant must be responding fast enough to fit in that window.

I will send a PR which fixes the issue for me shortly. It's small, but not exactly elegant. :)

The LLM's summary:

Root Cause

There is a race condition in stratus.start/1 (in build/packages/stratus/src/stratus.gleam) between:

1. Handshake completion - The WebSocket handshake is performed by the calling process (in our case, the OTP supervisor context)
2. Socket data arriving - Home Assistant sends auth_required immediately after handshake
3. Socket ownership transfer - controlling_process/2 transfers socket ownership to the new actor

The timeline is:

1. Handshake completes (socket owned by supervisor context)
2. Home Assistant sends auth_required message
3. SSL socket message arrives in SUPERVISOR's mailbox
4. controlling_process() transfers socket to actor
5. Actor starts with selector, but auth_required is already in supervisor's mailbox
6. Actor never receives auth_required, stays in AuthPending state forever
7. Dependent actors timeout waiting for HA responses
8. Supervisor crashes with init_failed

Evidence

From debug output:

[DEBG] Handshake successful
"HA init: stratus.selecting called"
[EROR] Supervisor received unexpected message: [Ssl(Sslsocket(...), <<compressed data>>)]

The SSL socket message with the auth_required data went to the supervisor instead of the HA actor.

The Bug Location

In stratus.gleam lines ~490-508:

|> actor.start
|> result.map_error(ActorFailed)
|> result.try(fn(started) {
  // PROBLEM: Socket is still owned by calling process at this point!
  // Any incoming data goes to calling process's mailbox.
  case transport {
    Tcp -> tcp.controlling_process(handshake_response.socket, started.pid)
    Ssl -> ssl.controlling_process(handshake_response.socket, started.pid)
  }
  // ...
})

The socket ownership transfer happens after actor.start returns, but by that time the server may have already sent data that ends up in the wrong mailbox.

[rawhat]

Can you test this with the latest main branch?

Edit: I don't have a reliable reproduction so it's difficult for me to test. If you do, that would be awesome.

[jhillyerd]

Yes. I'm traveling this week, so hopefully early next week.

[jhillyerd]

with stratus = { git = "git@github.com:rawhat/stratus.git", ref = "main" } & gleam clean, I still get the crash about 25% of the time, so it's improved but not fixed from what I can tell.

I'll see if I can build a standalone repro this weekend.

[rawhat]

That would be super helpful, thank you! I can keep thinking about this. Interestingly, haven't seen this with mist websockets, so maybe there's some difference there. I'll also poke around this weekend.

[jhillyerd]

I made some attempts at an automatic repro, but can't trigger this issue with or without SSL, even doing many parallel requests. I'm going to have to spend time time looking at my project and see if there is another explanation, or try to get it reproing there without SSL so I can tcpdump it.

[jhillyerd]

I managed to get my local project back to the point where it's logging the supervisor error:

EROR #(charlist.from_string("Supervisor received unexpected message: ~tp~n"), [Ssl(Sslsocket(//erl(#Port<0.4>), //erl(<0.142.0>), //erl(<0.141.0>), GenTcp, TlsGenConnection, //erl(#Ref<0.564512820.645791751.14436>), Undefined), <<193, 126, 0, 160, 236, 253, 9, 128, 28, 69, 249, 191, 129, 247, 102, 55, 215, 36, 155, 4, 64, 69, 69, 82, 4, 32, 9, 204, 46, 187, 155, 59, 129, 36, 187, 185, 33, 23, 73, 184, 4, 133, 222, 153, 222, 157, 38, 51, 211, 67, 247, 76, 54, 139, 8, 241, 86, 81, 193, 251, 86, 84, 196, 91, 81, 241, 22, 13, 137, 138, 55, 120, 223, 26, 69, 5, 239, 32, 170, 160, 144, 253, 255, 159, 247, 173, 158, 169, 221, 221, 112, 250, 253, 253, 190, 191, 255, 223, 205, 102, 103, 186, 187, 170, 234, 125, 223, 122, 235, 173, 79, 189, 245, 86, 245, 51, 102, 85, 7, 43, 193, 172, 165, 179, 252, 90, 181, 112, 113, 28, 92, 86, 11, 227, 32, 63, 43, 59, 171, 224, 95, 188, 43, 136, 147, 48, 42, 207, 90, 58, 171, 171, 163, 107, 65, 251, 146, 246, 121, 179, 158, 249, 255, 1>>)])

I messed around with logging the time difference between running my initializer fn (inside stratus) to successfully receiving the auth required message from home assistant, and it's only 2ms. I've also messed around with using the ts cli util to add timestamps the logs for both success and failures.

• Success: It's about 2.5ms from your Handshake successful log to my logging of the JSON content
• Failure: It's about 3.5ms from your Handshake log to the supervisor reporting the unexpected message.

Can't really draw any useful conclusions from that given they are logging different things, and we are waiting for a flush, shell pipeline, etc.

But at least I know it's not an LLM hallucination, and can try out different scenarios if you have ideas. I'll work on non-SSL now.

Update: I cannot make it fail over a regular HTTP connection, seems only HTTPS has the bug.

[rawhat]

It's late and I'll dig into this more tomorrow, but I think the issue is that the handshake happens in start which if you're running in a supervisor means it goes to that mailbox. I think instead it should be inside the init function. I will try that change tomorrow and push it up so you can try it.

[rawhat]

Hey sorry, bit late on this. Just pushed that change, hopefully resolves it for you 🙏🏻

Let me know if it does, whenever you get a chance to test it!

[jhillyerd]

Just tested, 0 failures in about 20 runs. I also retested previous main in case the phase of the moon was wrong, and it failed immediately, so I think this is a valid fix!

[rawhat]

Sweet! I do wanna test the behavior when the ws handshake request times out, but otherwise I'll push this out soon. Thanks for your patience 🙏